[March 28, 2025 at 10:53:45 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1048576000
22:53:45.504 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:45.504 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:53:45.504 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:53:45.505 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:53:45.505 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:53:45.505 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:53:45 PM UTC
22:53:45.505 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:45.505 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:45.505 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:53:45.505 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:53:45.505 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:53:45.506 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:53:45.506 INFO VariantRecalibrator - Deflater: IntelDeflater
22:53:45.506 INFO VariantRecalibrator - Inflater: IntelInflater
22:53:45.506 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:53:45.506 INFO VariantRecalibrator - Requester pays: disabled
22:53:45.506 INFO VariantRecalibrator - Initializing engine
22:53:45.510 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
22:53:45.547 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
22:53:45.647 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
22:53:45.683 INFO VariantRecalibrator - Done initializing engine
22:53:45.684 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
22:53:45.719 INFO ProgressMeter - Starting traversal
22:53:45.719 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:53:45.862 INFO ProgressMeter - chr1:6212018 0.0 2791 1179295.8
22:53:45.863 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
22:53:45.863 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
22:53:45.864 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
22:53:45.865 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
22:53:45.866 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
22:53:45.867 INFO VariantDataManager - AS_FS: mean = 1.08 standard deviation = 2.43
22:53:45.867 INFO VariantDataManager - AS_MQRankSum: mean = 0.00 standard deviation = 0.01
22:53:45.879 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
22:53:45.879 INFO VariantDataManager - Training with 2769 variants after standard deviation thresholding.
22:53:45.880 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:53:45.936 INFO VariantRecalibratorEngine - Finished iteration 0.
22:53:45.992 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.56007
22:53:46.034 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.67355
22:53:46.077 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 5.08559
22:53:46.120 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.01567
22:53:46.163 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.02021
22:53:46.192 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01989
22:53:46.217 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02504
22:53:46.243 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03657
22:53:46.268 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.04057
22:53:46.294 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.08648
22:53:46.320 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.01514
22:53:46.345 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00496
22:53:46.370 INFO VariantRecalibratorEngine - Finished iteration 65. Current change in mixture coefficients = 0.00163
22:53:46.370 INFO VariantRecalibratorEngine - Convergence after 65 iterations!
22:53:46.372 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
22:53:46.403 INFO VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
22:53:46.403 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:53:46.404 INFO VariantRecalibratorEngine - Finished iteration 0.
22:53:46.404 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
22:53:46.404 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
22:53:46.422 INFO TrancheManager - Finding 4 tranches for 2786 variants
22:53:46.423 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
22:53:46.423 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
22:53:46.423 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]
22:53:46.423 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
22:53:46.424 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
22:53:46.424 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]
22:53:46.424 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
22:53:46.424 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
22:53:46.424 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]
22:53:46.424 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
22:53:46.425 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
22:53:46.425 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]
22:53:46.426 INFO VariantRecalibrator - Writing out recalibration table...
22:53:46.468 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:53:46 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
22:53:46.470 INFO gatk - Initializing VQSR tests/resetting random number generator
[March 28, 2025 at 10:53:49 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
[March 28, 2025 at 10:53:52 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
22:53:52.291 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:52.291 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:53:52.291 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:53:52.291 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:53:52.291 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:53:52.291 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:53:52 PM UTC
22:53:52.291 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:52.291 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:52.292 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:53:52.292 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:53:52.292 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:53:52.292 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:53:52.292 INFO VariantRecalibrator - Deflater: IntelDeflater
22:53:52.292 INFO VariantRecalibrator - Inflater: IntelInflater
22:53:52.292 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:53:52.292 INFO VariantRecalibrator - Requester pays: disabled
22:53:52.292 INFO VariantRecalibrator - Initializing engine
22:53:52.294 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
22:53:52.306 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
22:53:52.353 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
22:53:52.371 INFO VariantRecalibrator - Done initializing engine
22:53:52.371 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
22:53:52.386 INFO ProgressMeter - Starting traversal
22:53:52.386 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:53:52.459 INFO ProgressMeter - chr1:6212018 0.0 2791 2293972.6
22:53:52.459 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
22:53:52.459 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
22:53:52.460 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
22:53:52.460 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
22:53:52.460 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
22:53:52.461 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
22:53:52.461 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
22:53:52.461 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:53:52.512 INFO VariantRecalibratorEngine - Finished iteration 0.
22:53:52.529 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.16919
22:53:52.546 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.14268
22:53:52.564 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.19617
22:53:52.582 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.09047
22:53:52.599 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.05235
22:53:52.616 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04028
22:53:52.634 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02103
22:53:52.651 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01461
22:53:52.669 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01136
22:53:52.686 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00583
22:53:52.703 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00291
22:53:52.714 INFO VariantRecalibratorEngine - Convergence after 58 iterations!
22:53:52.716 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
22:53:52.724 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
22:53:52.728 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:53:52 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
22:53:52.730 INFO gatk - Initializing VQSR tests/resetting random number generator
[March 28, 2025 at 10:53:52 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[March 28, 2025 at 10:53:52 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[March 28, 2025 at 10:53:53 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[March 28, 2025 at 10:53:55 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1048576000
22:53:55.432 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:55.432 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:53:55.432 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:53:55.433 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:53:55.433 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:53:55.433 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:53:55 PM UTC
22:53:55.433 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:55.433 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:55.433 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:53:55.433 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:53:55.433 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:53:55.433 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:53:55.434 INFO VariantRecalibrator - Deflater: IntelDeflater
22:53:55.434 INFO VariantRecalibrator - Inflater: IntelInflater
22:53:55.434 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:53:55.434 INFO VariantRecalibrator - Requester pays: disabled
22:53:55.434 INFO VariantRecalibrator - Initializing engine
22:53:55.435 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
22:53:55.437 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
22:53:55.438 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
22:53:55.440 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
22:53:55.442 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
22:53:55.443 INFO VariantRecalibrator - Done initializing engine
22:53:55.445 WARN VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
22:53:55.445 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
22:53:55.445 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
22:53:55.446 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
22:53:55.446 INFO ProgressMeter - Starting traversal
22:53:55.447 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:53:56.393 INFO ProgressMeter - 20:9944766 0.0 131821 8360740.0
22:53:56.393 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
22:53:56.396 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
22:53:56.400 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
22:53:56.403 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
22:53:56.425 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
22:53:56.427 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
22:53:56.427 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:53:56.685 INFO VariantRecalibratorEngine - Finished iteration 0.
22:53:56.795 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
22:53:56.907 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
22:53:57.023 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
22:53:57.114 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
22:53:57.205 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
22:53:57.294 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
22:53:57.386 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
22:53:57.478 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
22:53:57.570 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
22:53:57.662 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
22:53:57.735 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
22:53:57.742 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
22:53:57.814 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
22:53:57.814 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:53:57.815 INFO VariantRecalibratorEngine - Finished iteration 0.
22:53:57.816 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
22:53:57.818 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
22:53:58.010 INFO TrancheManager - Finding 4 tranches for 131821 variants
22:53:58.043 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
22:53:58.050 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
22:53:58.050 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]
22:53:58.050 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
22:53:58.055 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
22:53:58.055 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]
22:53:58.055 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
22:53:58.060 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
22:53:58.060 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]
22:53:58.060 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
22:53:58.064 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
22:53:58.064 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]
22:53:58.064 INFO VariantRecalibrator - Writing out recalibration table...
22:53:58.364 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:53:58 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
22:53:58.402 INFO gatk - Initializing VQSR tests/resetting random number generator
22:53:58.410 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:58.410 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:53:58.410 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:53:58.410 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:53:58.410 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:53:58.410 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:53:58 PM UTC
22:53:58.410 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:58.410 INFO VariantRecalibrator - ------------------------------------------------------------
22:53:58.410 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:53:58.410 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:53:58.411 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:53:58.411 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:53:58.411 INFO VariantRecalibrator - Deflater: IntelDeflater
22:53:58.411 INFO VariantRecalibrator - Inflater: IntelInflater
22:53:58.411 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:53:58.411 INFO VariantRecalibrator - Requester pays: disabled
22:53:58.411 INFO VariantRecalibrator - Initializing engine
22:53:58.412 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
22:53:58.414 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
22:53:58.416 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
22:53:58.418 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
22:53:58.421 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
22:53:58.422 INFO VariantRecalibrator - Done initializing engine
22:53:58.422 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
22:53:58.422 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
22:53:58.422 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
22:53:58.423 INFO ProgressMeter - Starting traversal
22:53:58.423 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:53:59.367 INFO ProgressMeter - 20:9944766 0.0 131821 8387338.3
22:53:59.368 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
22:53:59.370 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
22:53:59.375 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
22:53:59.379 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
22:53:59.405 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
22:53:59.406 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
22:53:59.407 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:53:59.668 INFO VariantRecalibratorEngine - Finished iteration 0.
22:53:59.785 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
22:53:59.872 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
22:53:59.960 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
22:54:00.050 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
22:54:00.140 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
22:54:00.228 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
22:54:00.319 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
22:54:00.412 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
22:54:00.503 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
22:54:00.596 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
22:54:00.677 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
22:54:00.689 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
22:54:00.768 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
22:54:00.768 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:00.769 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:00.770 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
22:54:00.772 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
22:54:00.953 INFO TrancheManager - Finding 4 tranches for 131821 variants
22:54:00.988 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
22:54:00.992 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
22:54:00.992 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]
22:54:00.992 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
22:54:00.999 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
22:54:00.999 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]
22:54:00.999 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
22:54:01.005 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
22:54:01.005 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]
22:54:01.005 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
22:54:01.010 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
22:54:01.010 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]
22:54:01.010 INFO VariantRecalibrator - Writing out recalibration table...
22:54:01.316 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:54:01 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
22:54:01.339 INFO gatk - Initializing VQSR tests/resetting random number generator
22:54:01.348 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:01.348 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:54:01.348 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:54:01.348 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:54:01.348 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:54:01.348 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:54:01 PM UTC
22:54:01.348 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:01.348 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:01.349 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:54:01.349 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:54:01.349 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:54:01.349 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:54:01.349 INFO VariantRecalibrator - Deflater: IntelDeflater
22:54:01.349 INFO VariantRecalibrator - Inflater: IntelInflater
22:54:01.349 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:54:01.349 INFO VariantRecalibrator - Requester pays: disabled
22:54:01.349 INFO VariantRecalibrator - Initializing engine
22:54:01.350 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
22:54:01.362 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
22:54:01.405 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
22:54:01.421 INFO VariantRecalibrator - Done initializing engine
22:54:01.421 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
22:54:01.433 INFO ProgressMeter - Starting traversal
22:54:01.433 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:54:01.481 INFO ProgressMeter - chr1:6212018 0.0 2791 3488750.0
22:54:01.481 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
22:54:01.481 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
22:54:01.481 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
22:54:01.482 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
22:54:01.482 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
22:54:01.482 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
22:54:01.482 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
22:54:01.483 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:01.513 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:01.529 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
22:54:01.545 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
22:54:01.560 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
22:54:01.576 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
22:54:01.592 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
22:54:01.607 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
22:54:01.623 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
22:54:01.639 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
22:54:01.655 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
22:54:01.670 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
22:54:01.686 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
22:54:01.702 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
22:54:01.702 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
22:54:01.703 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
22:54:01.712 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
22:54:01.712 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:01.712 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:01.712 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
22:54:01.712 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
22:54:01.720 INFO TrancheManager - Finding 4 tranches for 2786 variants
22:54:01.721 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
22:54:01.722 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
22:54:01.722 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]
22:54:01.722 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
22:54:01.722 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
22:54:01.722 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]
22:54:01.722 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
22:54:01.722 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
22:54:01.722 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]
22:54:01.722 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
22:54:01.723 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
22:54:01.723 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]
22:54:01.723 INFO VariantRecalibrator - Writing out recalibration table...
22:54:01.737 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:54:01 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
22:54:01.742 INFO gatk - Initializing VQSR tests/resetting random number generator
22:54:01.754 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:01.754 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:54:01.754 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:54:01.754 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:54:01.754 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:54:01.754 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:54:01 PM UTC
22:54:01.754 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:01.754 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:01.754 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:54:01.754 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:54:01.754 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:54:01.754 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:54:01.754 INFO VariantRecalibrator - Deflater: IntelDeflater
22:54:01.755 INFO VariantRecalibrator - Inflater: IntelInflater
22:54:01.755 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:54:01.755 INFO VariantRecalibrator - Requester pays: disabled
22:54:01.755 INFO VariantRecalibrator - Initializing engine
22:54:01.756 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
22:54:01.758 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
22:54:01.760 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
22:54:01.762 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
22:54:01.765 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
22:54:01.766 INFO VariantRecalibrator - Done initializing engine
22:54:01.766 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
22:54:01.766 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
22:54:01.766 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
22:54:01.767 INFO ProgressMeter - Starting traversal
22:54:01.767 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:54:02.727 INFO ProgressMeter - 20:9944766 0.0 131821 8238812.5
22:54:02.727 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
22:54:02.729 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
22:54:02.734 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
22:54:02.738 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
22:54:02.761 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
22:54:02.763 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
22:54:02.763 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:03.024 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:03.135 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
22:54:03.246 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
22:54:03.358 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
22:54:03.472 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
22:54:03.577 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
22:54:03.665 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
22:54:03.756 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
22:54:03.847 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
22:54:03.938 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
22:54:04.029 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
22:54:04.102 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
22:54:04.109 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
22:54:04.176 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
22:54:04.177 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:04.179 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:04.179 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
22:54:04.181 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
22:54:04.360 INFO TrancheManager - Finding 12 tranches for 131821 variants
22:54:04.400 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
22:54:04.405 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
22:54:04.405 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]
22:54:04.405 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
22:54:04.410 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001
22:54:04.410 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]
22:54:04.410 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
22:54:04.415 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
22:54:04.415 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]
22:54:04.415 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
22:54:04.419 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002
22:54:04.419 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]
22:54:04.419 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
22:54:04.423 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004
22:54:04.423 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]
22:54:04.423 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
22:54:04.428 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005
22:54:04.428 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]
22:54:04.428 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
22:54:04.433 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006
22:54:04.433 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]
22:54:04.433 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
22:54:04.437 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007
22:54:04.437 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]
22:54:04.437 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
22:54:04.441 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
22:54:04.442 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]
22:54:04.442 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
22:54:04.446 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020
22:54:04.446 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]
22:54:04.446 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
22:54:04.450 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030
22:54:04.450 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]
22:54:04.450 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
22:54:04.454 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
22:54:04.454 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]
22:54:04.454 INFO VariantRecalibrator - Writing out recalibration table...
22:54:04.762 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:54:04 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
22:54:04.785 INFO gatk - Initializing VQSR tests/resetting random number generator
22:54:04.795 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:04.795 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:54:04.795 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:54:04.795 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:54:04.796 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:54:04.796 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:54:04 PM UTC
22:54:04.796 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:04.796 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:04.796 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:54:04.796 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:54:04.796 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:54:04.796 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:54:04.796 INFO VariantRecalibrator - Deflater: IntelDeflater
22:54:04.796 INFO VariantRecalibrator - Inflater: IntelInflater
22:54:04.796 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:54:04.796 INFO VariantRecalibrator - Requester pays: disabled
22:54:04.796 INFO VariantRecalibrator - Initializing engine
22:54:04.798 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
22:54:04.809 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
22:54:04.843 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
22:54:04.858 INFO VariantRecalibrator - Done initializing engine
22:54:04.858 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
22:54:04.868 INFO ProgressMeter - Starting traversal
22:54:04.868 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:54:04.907 INFO ProgressMeter - chr1:6212018 0.0 2791 4293846.2
22:54:04.907 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
22:54:04.907 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
22:54:04.908 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
22:54:04.908 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
22:54:04.908 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
22:54:04.909 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
22:54:04.909 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
22:54:04.909 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:04.940 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:04.957 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
22:54:04.974 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
22:54:04.991 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
22:54:05.008 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
22:54:05.024 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
22:54:05.041 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
22:54:05.058 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
22:54:05.075 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
22:54:05.092 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
22:54:05.108 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
22:54:05.125 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
22:54:05.143 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
22:54:05.143 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
22:54:05.145 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
22:54:05.153 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
22:54:05.153 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:05.153 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:05.153 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
22:54:05.153 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
22:54:05.161 INFO TrancheManager - Finding 12 tranches for 2786 variants
22:54:05.162 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
22:54:05.162 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
22:54:05.162 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]
22:54:05.162 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
22:54:05.162 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001
22:54:05.162 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]
22:54:05.162 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
22:54:05.163 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
22:54:05.163 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]
22:54:05.163 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
22:54:05.163 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002
22:54:05.163 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]
22:54:05.163 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
22:54:05.163 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004
22:54:05.163 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]
22:54:05.164 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
22:54:05.164 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005
22:54:05.164 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]
22:54:05.164 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
22:54:05.164 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006
22:54:05.164 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]
22:54:05.164 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
22:54:05.164 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007
22:54:05.165 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]
22:54:05.165 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
22:54:05.165 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
22:54:05.165 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]
22:54:05.165 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
22:54:05.165 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020
22:54:05.165 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]
22:54:05.165 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
22:54:05.166 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030
22:54:05.166 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]
22:54:05.166 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
22:54:05.166 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
22:54:05.166 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]
22:54:05.166 INFO VariantRecalibrator - Writing out recalibration table...
22:54:05.186 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:54:05 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
22:54:05.189 INFO gatk - Initializing VQSR tests/resetting random number generator
[March 28, 2025 at 10:54:07 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
22:54:07.630 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:07.630 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:54:07.630 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:54:07.630 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:54:07.630 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:54:07.631 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:54:07 PM UTC
22:54:07.631 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:07.631 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:07.631 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:54:07.631 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:54:07.631 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:54:07.631 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:54:07.631 INFO VariantRecalibrator - Deflater: IntelDeflater
22:54:07.631 INFO VariantRecalibrator - Inflater: IntelInflater
22:54:07.631 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:54:07.631 INFO VariantRecalibrator - Requester pays: disabled
22:54:07.631 INFO VariantRecalibrator - Initializing engine
22:54:07.632 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
22:54:07.635 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
22:54:07.637 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
22:54:07.639 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
22:54:07.641 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
22:54:07.660 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
22:54:07.662 INFO VariantRecalibrator - Done initializing engine
22:54:07.662 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
22:54:07.662 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
22:54:07.662 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
22:54:07.666 INFO ProgressMeter - Starting traversal
22:54:07.666 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:54:08.672 INFO ProgressMeter - 20:9938789 0.0 134919 8046858.8
22:54:08.672 INFO ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
22:54:08.675 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
22:54:08.681 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
22:54:08.686 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
22:54:08.714 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
22:54:08.716 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
22:54:08.716 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:08.927 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:09.013 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.13181
22:54:09.102 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.46782
22:54:09.172 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 9.04961
22:54:09.241 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.04477
22:54:09.310 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01711
22:54:09.378 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.02053
22:54:09.447 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.01194
22:54:09.518 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01038
22:54:09.587 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.06192
22:54:09.657 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01281
22:54:09.729 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00457
22:54:09.759 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
22:54:09.764 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
22:54:09.855 INFO VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
22:54:09.855 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:09.857 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:09.859 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.05287
22:54:09.860 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.02030
22:54:09.861 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.00986
22:54:09.862 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.00749
22:54:09.864 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.00850
22:54:09.873 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01430
22:54:09.874 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02541
22:54:09.875 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.02173
22:54:09.876 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01024
22:54:09.877 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00479
22:54:09.878 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00245
22:54:09.879 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
22:54:09.881 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
22:54:10.053 INFO TrancheManager - Finding 4 tranches for 134603 variants
22:54:10.094 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
22:54:10.105 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
22:54:10.105 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]
22:54:10.105 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
22:54:10.118 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001
22:54:10.118 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.90 minVQSLod=-4.2626 known=(61478 @ 2.3089) novel=(72476 @ 2.2282) truthSites(18665 accessible, 18646 called), name=anonymous]
22:54:10.118 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
22:54:10.131 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010
22:54:10.131 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]
22:54:10.131 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
22:54:10.143 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100
22:54:10.143 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]
22:54:10.143 INFO VariantRecalibrator - Writing out recalibration table...
22:54:10.470 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:54:10 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
22:54:10.472 INFO gatk - Initializing VQSR tests/resetting random number generator
22:54:10.480 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:10.480 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
22:54:10.480 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
22:54:10.481 INFO VariantRecalibrator - Executing as runner@fv-az1690-153 on Linux v6.8.0-1021-azure amd64
22:54:10.481 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
22:54:10.481 INFO VariantRecalibrator - Start Date/Time: March 28, 2025 at 10:54:10 PM UTC
22:54:10.481 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:10.481 INFO VariantRecalibrator - ------------------------------------------------------------
22:54:10.481 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:54:10.481 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:54:10.481 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:54:10.481 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:54:10.481 INFO VariantRecalibrator - Deflater: IntelDeflater
22:54:10.481 INFO VariantRecalibrator - Inflater: IntelInflater
22:54:10.481 INFO VariantRecalibrator - GCS max retries/reopens: 20
22:54:10.481 INFO VariantRecalibrator - Requester pays: disabled
22:54:10.481 INFO VariantRecalibrator - Initializing engine
22:54:10.482 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
22:54:10.484 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
22:54:10.485 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
22:54:10.486 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
22:54:10.488 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
22:54:10.489 INFO VariantRecalibrator - Done initializing engine
22:54:10.489 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
22:54:10.489 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
22:54:10.489 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
22:54:10.490 INFO ProgressMeter - Starting traversal
22:54:10.490 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
22:54:11.520 INFO ProgressMeter - 20:9944766 0.0 131821 7686355.7
22:54:11.520 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
22:54:11.522 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
22:54:11.528 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
22:54:11.534 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
22:54:11.563 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
22:54:11.565 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
22:54:11.565 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:11.829 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:11.948 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
22:54:12.033 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
22:54:12.121 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
22:54:12.211 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
22:54:12.303 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
22:54:12.392 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
22:54:12.483 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
22:54:12.576 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
22:54:12.667 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
22:54:12.762 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
22:54:12.842 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
22:54:12.849 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
22:54:12.919 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
22:54:12.919 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
22:54:12.920 INFO VariantRecalibratorEngine - Finished iteration 0.
22:54:12.921 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
22:54:12.923 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
22:54:13.109 INFO TrancheManager - Finding 12 tranches for 131821 variants
22:54:13.143 INFO TrancheManager - VQSLODTranche threshold 10.00 => selection metric threshold 0.900
22:54:13.153 INFO TrancheManager - Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262
22:54:13.153 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
22:54:13.153 INFO TrancheManager - VQSLODTranche threshold 8.00 => selection metric threshold 0.920
22:54:13.158 INFO TrancheManager - Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114
22:54:13.158 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
22:54:13.158 INFO TrancheManager - VQSLODTranche threshold 6.00 => selection metric threshold 0.940
22:54:13.163 INFO TrancheManager - Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052
22:54:13.163 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
22:54:13.163 INFO TrancheManager - VQSLODTranche threshold 4.00 => selection metric threshold 0.960
22:54:13.168 INFO TrancheManager - Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023
22:54:13.168 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
22:54:13.168 INFO TrancheManager - VQSLODTranche threshold 2.00 => selection metric threshold 0.980
22:54:13.172 INFO TrancheManager - Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009
22:54:13.172 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
22:54:13.172 INFO TrancheManager - VQSLODTranche threshold 0.00 => selection metric threshold 1.000
22:54:13.177 INFO TrancheManager - Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004
22:54:13.177 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
22:54:13.177 INFO TrancheManager - VQSLODTranche threshold -2.00 => selection metric threshold 1.020
22:54:13.182 INFO TrancheManager - Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001
22:54:13.182 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
22:54:13.182 INFO TrancheManager - VQSLODTranche threshold -4.00 => selection metric threshold 1.040
22:54:13.188 INFO TrancheManager - Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001
22:54:13.188 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
22:54:13.188 INFO TrancheManager - VQSLODTranche threshold -6.00 => selection metric threshold 1.060
22:54:13.192 INFO TrancheManager - Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001
22:54:13.193 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
22:54:13.193 INFO TrancheManager - VQSLODTranche threshold -8.00 => selection metric threshold 1.080
22:54:13.197 INFO TrancheManager - Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000
22:54:13.197 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
22:54:13.197 INFO TrancheManager - VQSLODTranche threshold -10.00 => selection metric threshold 1.100
22:54:13.202 INFO TrancheManager - Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000
22:54:13.202 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
22:54:13.202 INFO TrancheManager - VQSLODTranche threshold -12.00 => selection metric threshold 1.120
22:54:13.208 INFO TrancheManager - Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000
22:54:13.208 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
22:54:13.208 INFO VariantRecalibrator - Writing out recalibration table...
22:54:13.506 INFO VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
22:54:13.510 INFO VariantRecalibrator - Shutting down engine
[March 28, 2025 at 10:54:13 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
[March 28, 2025 at 10:55:21 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1178599424