[May 19, 2025 at 4:11:29 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1048576000
16:11:29.412 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:29.412 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:29.413 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:29.413 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:29.413 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:29.413 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:29 PM GMT
16:11:29.413 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:29.413 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:29.414 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:29.414 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:29.414 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:29.414 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:29.414 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:29.414 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:29.414 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:29.414 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:29.414 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:29.414 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:29.414 INFO VariantRecalibrator - Requester pays: disabled
16:11:29.415 INFO VariantRecalibrator - Initializing engine
16:11:29.419 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:11:29.450 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:11:29.540 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
16:11:29.576 INFO VariantRecalibrator - Done initializing engine
16:11:29.576 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
16:11:29.611 INFO ProgressMeter - Starting traversal
16:11:29.611 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:29.759 INFO ProgressMeter - chr1:6212018 0.0 2791 1139183.7
16:11:29.759 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:11:29.760 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
16:11:29.761 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
16:11:29.762 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
16:11:29.763 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
16:11:29.763 INFO VariantDataManager - AS_FS: mean = 1.08 standard deviation = 2.43
16:11:29.764 INFO VariantDataManager - AS_MQRankSum: mean = 0.00 standard deviation = 0.01
16:11:29.776 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
16:11:29.777 INFO VariantDataManager - Training with 2769 variants after standard deviation thresholding.
16:11:29.777 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:29.835 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:29.878 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.56007
16:11:29.922 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.67355
16:11:29.960 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 5.08559
16:11:29.992 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.01567
16:11:30.027 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.02021
16:11:30.054 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01989
16:11:30.087 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02504
16:11:30.113 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03657
16:11:30.139 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.04057
16:11:30.167 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.08648
16:11:30.202 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.01514
16:11:30.228 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00496
16:11:30.254 INFO VariantRecalibratorEngine - Finished iteration 65. Current change in mixture coefficients = 0.00163
16:11:30.254 INFO VariantRecalibratorEngine - Convergence after 65 iterations!
16:11:30.257 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:11:30.303 INFO VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
16:11:30.303 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:30.303 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:30.303 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
16:11:30.304 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:11:30.331 INFO TrancheManager - Finding 4 tranches for 2786 variants
16:11:30.332 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:11:30.332 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
16:11:30.333 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]
16:11:30.333 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:11:30.333 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
16:11:30.333 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]
16:11:30.333 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:11:30.334 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
16:11:30.334 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]
16:11:30.334 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:11:30.334 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
16:11:30.334 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]
16:11:30.335 INFO VariantRecalibrator - Writing out recalibration table...
16:11:30.385 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:30 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000
16:11:30.387 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 4:11:33 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 4:11:35 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
16:11:35.904 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:35.904 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:35.904 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:35.904 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:35.905 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:35.905 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:35 PM GMT
16:11:35.905 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:35.905 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:35.905 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:35.905 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:35.905 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:35.905 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:35.906 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:35.906 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:35.906 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:35.906 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:35.906 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:35.906 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:35.906 INFO VariantRecalibrator - Requester pays: disabled
16:11:35.906 INFO VariantRecalibrator - Initializing engine
16:11:35.908 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:11:35.920 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:11:35.958 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
16:11:35.975 INFO VariantRecalibrator - Done initializing engine
16:11:35.975 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
16:11:35.988 INFO ProgressMeter - Starting traversal
16:11:35.988 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:36.050 INFO ProgressMeter - chr1:6212018 0.0 2791 2700967.7
16:11:36.050 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:11:36.050 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
16:11:36.050 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
16:11:36.051 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
16:11:36.051 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
16:11:36.052 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:11:36.052 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:11:36.052 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:36.082 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:36.100 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.16919
16:11:36.117 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.14268
16:11:36.134 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.19617
16:11:36.152 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.09047
16:11:36.169 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.05235
16:11:36.186 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04028
16:11:36.203 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02103
16:11:36.220 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01461
16:11:36.237 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01136
16:11:36.254 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00583
16:11:36.271 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00291
16:11:36.282 INFO VariantRecalibratorEngine - Convergence after 58 iterations!
16:11:36.283 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:11:36.292 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
16:11:36.297 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:36 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
16:11:36.299 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 4:11:36 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 4:11:36 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 4:11:37 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 4:11:39 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1048576000
16:11:39.201 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:39.201 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:39.201 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:39.202 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:39.202 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:39.202 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:39 PM GMT
16:11:39.202 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:39.202 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:39.202 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:39.202 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:39.202 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:39.202 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:39.202 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:39.203 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:39.203 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:39.203 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:39.203 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:39.203 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:39.203 INFO VariantRecalibrator - Requester pays: disabled
16:11:39.203 INFO VariantRecalibrator - Initializing engine
16:11:39.204 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:11:39.206 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:11:39.208 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:11:39.209 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:11:39.212 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
16:11:39.213 INFO VariantRecalibrator - Done initializing engine
16:11:39.215 WARN VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
16:11:39.215 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
16:11:39.215 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
16:11:39.215 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
16:11:39.217 INFO ProgressMeter - Starting traversal
16:11:39.217 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:40.217 INFO ProgressMeter - 20:9944766 0.0 131821 7917177.2
16:11:40.217 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:11:40.219 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
16:11:40.224 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
16:11:40.228 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
16:11:40.255 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:11:40.257 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:11:40.257 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:40.504 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:40.603 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
16:11:40.688 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
16:11:40.774 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
16:11:40.862 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
16:11:40.951 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
16:11:41.039 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
16:11:41.129 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
16:11:41.220 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
16:11:41.311 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
16:11:41.410 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
16:11:41.484 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
16:11:41.491 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:11:41.562 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:11:41.562 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:41.564 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:41.564 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
16:11:41.566 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:11:41.750 INFO TrancheManager - Finding 4 tranches for 131821 variants
16:11:41.783 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:11:41.787 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
16:11:41.787 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]
16:11:41.787 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:11:41.791 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
16:11:41.792 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]
16:11:41.792 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:11:41.796 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
16:11:41.796 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]
16:11:41.796 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:11:41.800 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
16:11:41.800 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]
16:11:41.801 INFO VariantRecalibrator - Writing out recalibration table...
16:11:42.096 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:42 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:11:42.125 INFO gatk - Initializing VQSR tests/resetting random number generator
16:11:42.144 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:42.144 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:42.144 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:42.145 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:42.145 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:42.145 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:42 PM GMT
16:11:42.145 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:42.145 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:42.145 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:42.145 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:42.145 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:42.145 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:42.146 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:42.146 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:42.146 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:42.146 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:42.146 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:42.146 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:42.146 INFO VariantRecalibrator - Requester pays: disabled
16:11:42.146 INFO VariantRecalibrator - Initializing engine
16:11:42.147 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:11:42.149 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:11:42.150 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:11:42.152 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:11:42.154 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
16:11:42.155 INFO VariantRecalibrator - Done initializing engine
16:11:42.155 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
16:11:42.155 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
16:11:42.155 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
16:11:42.156 INFO ProgressMeter - Starting traversal
16:11:42.156 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:43.127 INFO ProgressMeter - 20:9944766 0.0 131821 8145478.9
16:11:43.127 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:11:43.129 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
16:11:43.132 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
16:11:43.134 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
16:11:43.155 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:11:43.157 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:11:43.157 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:43.406 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:43.513 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
16:11:43.623 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
16:11:43.734 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
16:11:43.845 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
16:11:43.957 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
16:11:44.067 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
16:11:44.183 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
16:11:44.294 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
16:11:44.385 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
16:11:44.477 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
16:11:44.550 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
16:11:44.557 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:11:44.628 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:11:44.628 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:44.630 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:44.630 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
16:11:44.632 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:11:44.825 INFO TrancheManager - Finding 4 tranches for 131821 variants
16:11:44.859 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:11:44.863 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
16:11:44.863 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]
16:11:44.863 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:11:44.867 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
16:11:44.868 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]
16:11:44.868 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:11:44.872 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
16:11:44.872 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]
16:11:44.872 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:11:44.876 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
16:11:44.876 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]
16:11:44.876 INFO VariantRecalibrator - Writing out recalibration table...
16:11:45.177 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:45 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:11:45.199 INFO gatk - Initializing VQSR tests/resetting random number generator
16:11:45.218 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:45.218 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:45.218 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:45.218 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:45.218 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:45.218 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:45 PM GMT
16:11:45.218 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:45.218 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:45.219 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:45.219 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:45.219 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:45.219 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:45.219 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:45.219 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:45.219 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:45.219 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:45.219 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:45.219 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:45.219 INFO VariantRecalibrator - Requester pays: disabled
16:11:45.219 INFO VariantRecalibrator - Initializing engine
16:11:45.221 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:11:45.234 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:11:45.280 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
16:11:45.305 INFO VariantRecalibrator - Done initializing engine
16:11:45.306 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
16:11:45.320 INFO ProgressMeter - Starting traversal
16:11:45.320 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:45.374 INFO ProgressMeter - chr1:6212018 0.0 2791 3101111.1
16:11:45.374 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:11:45.375 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
16:11:45.375 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
16:11:45.375 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
16:11:45.375 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
16:11:45.376 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:11:45.376 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:11:45.376 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:45.406 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:45.423 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
16:11:45.439 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
16:11:45.456 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
16:11:45.473 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
16:11:45.490 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
16:11:45.507 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
16:11:45.523 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
16:11:45.540 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
16:11:45.557 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
16:11:45.574 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
16:11:45.591 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
16:11:45.608 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
16:11:45.608 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
16:11:45.609 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:11:45.618 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
16:11:45.618 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:45.618 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:45.618 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
16:11:45.618 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:11:45.626 INFO TrancheManager - Finding 4 tranches for 2786 variants
16:11:45.628 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:11:45.628 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
16:11:45.628 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]
16:11:45.628 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:11:45.628 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
16:11:45.628 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]
16:11:45.628 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:11:45.629 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
16:11:45.629 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]
16:11:45.629 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:11:45.629 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
16:11:45.629 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]
16:11:45.629 INFO VariantRecalibrator - Writing out recalibration table...
16:11:45.643 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:45 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
16:11:45.647 INFO gatk - Initializing VQSR tests/resetting random number generator
16:11:45.665 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:45.665 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:45.665 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:45.665 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:45.665 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:45.665 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:45 PM GMT
16:11:45.665 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:45.665 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:45.666 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:45.666 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:45.666 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:45.666 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:45.666 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:45.666 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:45.666 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:45.666 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:45.666 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:45.666 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:45.666 INFO VariantRecalibrator - Requester pays: disabled
16:11:45.666 INFO VariantRecalibrator - Initializing engine
16:11:45.667 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:11:45.669 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:11:45.670 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:11:45.672 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:11:45.676 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
16:11:45.677 INFO VariantRecalibrator - Done initializing engine
16:11:45.677 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
16:11:45.677 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
16:11:45.677 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
16:11:45.678 INFO ProgressMeter - Starting traversal
16:11:45.678 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:46.650 INFO ProgressMeter - 20:9944766 0.0 131821 8145478.9
16:11:46.650 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:11:46.652 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
16:11:46.656 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
16:11:46.660 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
16:11:46.687 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:11:46.689 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:11:46.689 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:46.934 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:47.033 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
16:11:47.117 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
16:11:47.205 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
16:11:47.295 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
16:11:47.386 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
16:11:47.474 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
16:11:47.565 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
16:11:47.656 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
16:11:47.747 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
16:11:47.847 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
16:11:47.920 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
16:11:47.927 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:11:47.993 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:11:47.993 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:47.994 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:47.995 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
16:11:47.997 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:11:48.177 INFO TrancheManager - Finding 12 tranches for 131821 variants
16:11:48.224 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:11:48.228 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
16:11:48.229 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]
16:11:48.229 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
16:11:48.233 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001
16:11:48.233 INFO TrancheManager - TruthSensitivityTranche is TruthSensitivityTranche targetTruthSensitivity=99.95 minVQSLod=-6.6729 known=(59316 @ 2.3020) novel=(72124 @ 2.2259) truthSites(18665 accessible, 18655 called), name=anonymous]
16:11:48.233 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:11:48.238 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
16:11:48.238 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]
16:11:48.238 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
16:11:48.242 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002
16:11:48.242 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]
16:11:48.242 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
16:11:48.247 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004
16:11:48.247 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]
16:11:48.247 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
16:11:48.251 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005
16:11:48.251 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]
16:11:48.251 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
16:11:48.255 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006
16:11:48.255 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]
16:11:48.255 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
16:11:48.260 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007
16:11:48.260 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]
16:11:48.260 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:11:48.264 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
16:11:48.264 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]
16:11:48.264 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
16:11:48.268 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020
16:11:48.269 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]
16:11:48.269 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
16:11:48.273 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030
16:11:48.273 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]
16:11:48.273 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:11:48.277 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
16:11:48.277 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]
16:11:48.278 INFO VariantRecalibrator - Writing out recalibration table...
16:11:48.573 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:48 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:11:48.595 INFO gatk - Initializing VQSR tests/resetting random number generator
16:11:48.624 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:48.624 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:48.624 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:48.624 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:48.624 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:48.624 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:48 PM GMT
16:11:48.624 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:48.625 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:48.625 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:48.625 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:48.625 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:48.625 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:48.625 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:48.625 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:48.625 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:48.625 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:48.625 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:48.625 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:48.625 INFO VariantRecalibrator - Requester pays: disabled
16:11:48.625 INFO VariantRecalibrator - Initializing engine
16:11:48.626 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:11:48.637 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/chr1snippet.doctoredMQ.sites_only.vcf.gz
16:11:48.672 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
16:11:48.693 INFO VariantRecalibrator - Done initializing engine
16:11:48.693 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
16:11:48.706 INFO ProgressMeter - Starting traversal
16:11:48.707 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:48.766 INFO ProgressMeter - chr1:6212018 0.0 2791 2838305.1
16:11:48.766 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
16:11:48.766 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
16:11:48.766 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
16:11:48.767 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
16:11:48.767 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
16:11:48.767 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
16:11:48.767 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
16:11:48.767 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:48.798 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:48.815 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
16:11:48.832 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
16:11:48.849 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
16:11:48.865 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
16:11:48.882 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
16:11:48.901 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
16:11:48.917 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
16:11:48.934 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
16:11:48.951 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
16:11:48.968 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
16:11:48.985 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
16:11:49.002 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
16:11:49.002 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
16:11:49.004 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:11:49.013 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
16:11:49.013 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:49.013 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:49.013 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
16:11:49.013 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
16:11:49.021 INFO TrancheManager - Finding 12 tranches for 2786 variants
16:11:49.021 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:11:49.021 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
16:11:49.021 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]
16:11:49.022 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
16:11:49.022 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001
16:11:49.022 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]
16:11:49.022 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:11:49.022 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
16:11:49.022 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]
16:11:49.022 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
16:11:49.023 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002
16:11:49.023 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]
16:11:49.023 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
16:11:49.023 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004
16:11:49.023 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]
16:11:49.023 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
16:11:49.023 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005
16:11:49.023 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]
16:11:49.023 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
16:11:49.024 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006
16:11:49.024 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]
16:11:49.024 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
16:11:49.024 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007
16:11:49.024 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]
16:11:49.024 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:11:49.024 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
16:11:49.024 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]
16:11:49.024 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
16:11:49.024 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020
16:11:49.025 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]
16:11:49.025 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
16:11:49.025 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030
16:11:49.025 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]
16:11:49.025 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:11:49.025 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
16:11:49.025 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]
16:11:49.025 INFO VariantRecalibrator - Writing out recalibration table...
16:11:49.038 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:49 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1048576000
16:11:49.041 INFO gatk - Initializing VQSR tests/resetting random number generator
[May 19, 2025 at 4:11:51 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.04 minutes.
Runtime.totalMemory()=1048576000
16:11:51.495 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:51.495 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:51.495 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:51.495 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:51.495 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:51.495 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:51 PM GMT
16:11:51.495 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:51.495 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:51.496 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:51.496 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:51.496 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:51.496 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:51.496 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:51.496 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:51.496 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:51.496 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:51.496 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:51.496 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:51.496 INFO VariantRecalibrator - Requester pays: disabled
16:11:51.496 INFO VariantRecalibrator - Initializing engine
16:11:51.497 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:11:51.499 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:11:51.500 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:11:51.502 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:11:51.504 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/g94982_20_1m_10m_python_2dcnn.indels.vcf.gz
16:11:51.517 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
16:11:51.518 INFO VariantRecalibrator - Done initializing engine
16:11:51.519 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
16:11:51.519 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
16:11:51.519 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
16:11:51.521 INFO ProgressMeter - Starting traversal
16:11:51.521 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:52.533 INFO ProgressMeter - 20:9938789 0.0 134919 7999150.2
16:11:52.533 INFO ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
16:11:52.536 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
16:11:52.539 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
16:11:52.542 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
16:11:52.567 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:11:52.569 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:11:52.569 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:52.769 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:52.850 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.13181
16:11:52.932 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.46782
16:11:53.017 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 9.04961
16:11:53.107 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.04477
16:11:53.176 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01711
16:11:53.244 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.02053
16:11:53.313 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.01194
16:11:53.381 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01038
16:11:53.450 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.06192
16:11:53.519 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01281
16:11:53.589 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00457
16:11:53.617 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
16:11:53.623 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
16:11:53.712 INFO VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
16:11:53.712 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:53.714 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:53.716 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.05287
16:11:53.717 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.02030
16:11:53.718 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.00986
16:11:53.719 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.00749
16:11:53.720 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.00850
16:11:53.722 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01430
16:11:53.723 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02541
16:11:53.724 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.02173
16:11:53.725 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01024
16:11:53.726 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00479
16:11:53.727 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00245
16:11:53.728 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
16:11:53.730 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
16:11:53.900 INFO TrancheManager - Finding 4 tranches for 134603 variants
16:11:53.936 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
16:11:53.941 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
16:11:53.941 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]
16:11:53.941 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
16:11:53.946 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001
16:11:53.946 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]
16:11:53.946 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
16:11:53.951 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010
16:11:53.951 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]
16:11:53.951 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
16:11:53.955 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100
16:11:53.955 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]
16:11:53.956 INFO VariantRecalibrator - Writing out recalibration table...
16:11:54.273 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:54 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
16:11:54.275 INFO gatk - Initializing VQSR tests/resetting random number generator
16:11:54.293 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:54.293 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.6.2.0-4-ga6bd333-SNAPSHOT
16:11:54.293 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
16:11:54.293 INFO VariantRecalibrator - Executing as root@67ac59543751 on Linux v6.11.0-1014-azure amd64
16:11:54.293 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.12+7-Ubuntu-1ubuntu222.04
16:11:54.293 INFO VariantRecalibrator - Start Date/Time: May 19, 2025 at 4:11:54 PM GMT
16:11:54.293 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:54.294 INFO VariantRecalibrator - ------------------------------------------------------------
16:11:54.294 INFO VariantRecalibrator - HTSJDK Version: test_cram_wiring-SNAPSHOT
16:11:54.294 INFO VariantRecalibrator - Picard Version: 3.4.0
16:11:54.294 INFO VariantRecalibrator - Built for Spark Version: 3.5.0
16:11:54.294 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
16:11:54.294 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
16:11:54.294 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
16:11:54.294 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
16:11:54.294 INFO VariantRecalibrator - Deflater: IntelDeflater
16:11:54.294 INFO VariantRecalibrator - Inflater: IntelInflater
16:11:54.294 INFO VariantRecalibrator - GCS max retries/reopens: 20
16:11:54.294 INFO VariantRecalibrator - Requester pays: disabled
16:11:54.294 INFO VariantRecalibrator - Initializing engine
16:11:54.296 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/dbsnp_132_b37.leftAligned.20.1M-10M.vcf
16:11:54.298 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/sites_r27_nr.b37_fwd.20.1M-10M.vcf
16:11:54.299 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/Omni25_sites_1525_samples.b37.20.1M-10M.vcf
16:11:54.301 INFO FeatureManager - Using codec VCFCodec to read file file:///gatkCloneMountPoint/src/test/resources/large/VQSR/phase1.projectConsensus.chr20.1M-10M.raw.snps.vcf
16:11:54.303 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
16:11:54.304 INFO VariantRecalibrator - Done initializing engine
16:11:54.304 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
16:11:54.304 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
16:11:54.304 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
16:11:54.305 INFO ProgressMeter - Starting traversal
16:11:54.305 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
16:11:55.267 INFO ProgressMeter - 20:9944766 0.0 131821 8221684.0
16:11:55.267 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
16:11:55.270 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
16:11:55.273 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
16:11:55.276 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
16:11:55.300 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
16:11:55.302 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
16:11:55.302 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:55.549 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:55.655 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
16:11:55.772 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
16:11:55.860 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
16:11:55.947 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
16:11:56.035 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
16:11:56.124 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
16:11:56.214 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
16:11:56.304 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
16:11:56.396 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
16:11:56.487 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
16:11:56.560 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
16:11:56.567 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:11:56.644 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
16:11:56.644 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
16:11:56.645 INFO VariantRecalibratorEngine - Finished iteration 0.
16:11:56.646 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
16:11:56.647 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
16:11:56.832 INFO TrancheManager - Finding 12 tranches for 131821 variants
16:11:56.866 INFO TrancheManager - VQSLODTranche threshold 10.00 => selection metric threshold 0.900
16:11:56.877 INFO TrancheManager - Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262
16:11:56.877 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
16:11:56.877 INFO TrancheManager - VQSLODTranche threshold 8.00 => selection metric threshold 0.920
16:11:56.882 INFO TrancheManager - Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114
16:11:56.882 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
16:11:56.882 INFO TrancheManager - VQSLODTranche threshold 6.00 => selection metric threshold 0.940
16:11:56.887 INFO TrancheManager - Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052
16:11:56.887 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
16:11:56.887 INFO TrancheManager - VQSLODTranche threshold 4.00 => selection metric threshold 0.960
16:11:56.891 INFO TrancheManager - Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023
16:11:56.892 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
16:11:56.892 INFO TrancheManager - VQSLODTranche threshold 2.00 => selection metric threshold 0.980
16:11:56.896 INFO TrancheManager - Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009
16:11:56.896 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
16:11:56.896 INFO TrancheManager - VQSLODTranche threshold 0.00 => selection metric threshold 1.000
16:11:56.901 INFO TrancheManager - Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004
16:11:56.901 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
16:11:56.901 INFO TrancheManager - VQSLODTranche threshold -2.00 => selection metric threshold 1.020
16:11:56.905 INFO TrancheManager - Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001
16:11:56.905 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
16:11:56.905 INFO TrancheManager - VQSLODTranche threshold -4.00 => selection metric threshold 1.040
16:11:56.910 INFO TrancheManager - Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001
16:11:56.910 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
16:11:56.910 INFO TrancheManager - VQSLODTranche threshold -6.00 => selection metric threshold 1.060
16:11:56.914 INFO TrancheManager - Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001
16:11:56.914 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
16:11:56.914 INFO TrancheManager - VQSLODTranche threshold -8.00 => selection metric threshold 1.080
16:11:56.918 INFO TrancheManager - Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000
16:11:56.919 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
16:11:56.919 INFO TrancheManager - VQSLODTranche threshold -10.00 => selection metric threshold 1.100
16:11:56.923 INFO TrancheManager - Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000
16:11:56.923 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
16:11:56.923 INFO TrancheManager - VQSLODTranche threshold -12.00 => selection metric threshold 1.120
16:11:56.927 INFO TrancheManager - Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000
16:11:56.927 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
16:11:56.928 INFO VariantRecalibrator - Writing out recalibration table...
16:11:57.222 INFO VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
16:11:57.226 INFO VariantRecalibrator - Shutting down engine
[May 19, 2025 at 4:11:57 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1048576000
[May 19, 2025 at 4:12:58 PM GMT] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=1048576000