[October 27, 2025 at 5:57:04 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.07 minutes.
Runtime.totalMemory()=887095296
17:57:04.973 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:04.976 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression10160427700573161676.so: /tmp/libgkl_compression10160427700573161676.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:04.977 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:04.980 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression11703130424888722114.so: /tmp/libgkl_compression11703130424888722114.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:04.982 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:04.982 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:04.982 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:04.983 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:04.983 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:04.983 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:04 PM UTC
17:57:04.983 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:04.983 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:04.983 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:04.983 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:04.983 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:04.984 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:04.984 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:04.984 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:04.984 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:04.984 INFO VariantRecalibrator - Requester pays: disabled
17:57:04.984 INFO VariantRecalibrator - Initializing engine
17:57:04.985 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:04.987 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
17:57:04.987 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:04.988 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:04.989 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:05.001 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:05.003 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
17:57:05.003 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:05.003 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:05.004 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:05.017 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:05.017 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:05.018 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:05.054 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
17:57:05.070 INFO VariantRecalibrator - Done initializing engine
17:57:05.071 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
17:57:05.089 INFO ProgressMeter - Starting traversal
17:57:05.089 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:05.187 INFO ProgressMeter - chr1:6212018 0.0 2791 1708775.5
17:57:05.187 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
17:57:05.188 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
17:57:05.189 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
17:57:05.190 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
17:57:05.191 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
17:57:05.192 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
17:57:05.193 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
17:57:05.193 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:05.251 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:05.279 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.16919
17:57:05.306 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.14268
17:57:05.344 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.19617
17:57:05.364 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.09047
17:57:05.383 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.05235
17:57:05.403 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04028
17:57:05.422 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02103
17:57:05.442 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01461
17:57:05.461 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01136
17:57:05.481 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00583
17:57:05.500 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00291
17:57:05.512 INFO VariantRecalibratorEngine - Convergence after 58 iterations!
17:57:05.514 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
17:57:05.527 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.5000.
17:57:05.534 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:05 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=887095296
17:57:05.539 INFO gatk - Initializing VQSR tests/resetting random number generator
17:57:05.549 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:05.553 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression902580168528335939.so: /tmp/libgkl_compression902580168528335939.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:05.553 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:05.557 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression3904943457285463500.so: /tmp/libgkl_compression3904943457285463500.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:05.558 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:05.559 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:05.559 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:05.559 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:05.559 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:05.559 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:05 PM UTC
17:57:05.559 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:05.559 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:05.559 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:05.559 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:05.559 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:05.559 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:05.559 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:05.559 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:05.559 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:05.559 INFO VariantRecalibrator - Requester pays: disabled
17:57:05.559 INFO VariantRecalibrator - Initializing engine
17:57:05.561 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
17:57:05.564 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
17:57:05.566 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
17:57:05.567 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
17:57:05.571 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
17:57:05.572 INFO VariantRecalibrator - Done initializing engine
17:57:05.573 WARN VariantDataManager - Ignoring duplicate annotations for recalibration [HRun]
17:57:05.574 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
17:57:05.574 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
17:57:05.574 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
17:57:05.576 INFO ProgressMeter - Starting traversal
17:57:05.576 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:06.714 INFO ProgressMeter - 20:9944766 0.0 131821 6950140.6
17:57:06.715 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
17:57:06.722 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
17:57:06.729 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
17:57:06.734 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
17:57:06.763 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
17:57:06.766 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
17:57:06.766 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:07.208 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:07.433 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
17:57:07.637 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
17:57:07.844 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
17:57:08.028 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
17:57:08.156 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
17:57:08.267 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
17:57:08.375 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
17:57:08.484 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
17:57:08.592 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
17:57:08.700 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
17:57:08.787 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
17:57:08.794 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
17:57:08.878 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
17:57:08.879 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:08.880 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:08.881 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
17:57:08.883 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
17:57:09.181 INFO TrancheManager - Finding 4 tranches for 131821 variants
17:57:09.233 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
17:57:09.255 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
17:57:09.256 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]
17:57:09.256 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
17:57:09.279 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
17:57:09.280 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]
17:57:09.280 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
17:57:09.303 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
17:57:09.304 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]
17:57:09.304 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
17:57:09.326 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
17:57:09.326 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]
17:57:09.327 INFO VariantRecalibrator - Writing out recalibration table...
17:57:09.731 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:09 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.07 minutes.
Runtime.totalMemory()=1000341504
17:57:09.764 INFO gatk - Initializing VQSR tests/resetting random number generator
17:57:09.776 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:09.779 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression12139454579503475362.so: /tmp/libgkl_compression12139454579503475362.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:09.780 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:09.783 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression14533937534508078840.so: /tmp/libgkl_compression14533937534508078840.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:09.785 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:09.785 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:09.785 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:09.785 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:09.785 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:09.785 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:09 PM UTC
17:57:09.785 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:09.785 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:09.785 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:09.785 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:09.785 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:09.785 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:09.786 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:09.786 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:09.786 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:09.786 INFO VariantRecalibrator - Requester pays: disabled
17:57:09.786 INFO VariantRecalibrator - Initializing engine
17:57:09.787 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
17:57:09.790 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
17:57:09.792 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
17:57:09.797 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
17:57:09.800 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
17:57:09.800 INFO VariantRecalibrator - Done initializing engine
17:57:09.801 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
17:57:09.801 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
17:57:09.801 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
17:57:09.802 INFO ProgressMeter - Starting traversal
17:57:09.802 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:10.890 INFO ProgressMeter - 20:9944766 0.0 131821 7276228.2
17:57:10.890 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
17:57:10.894 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
17:57:10.903 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
17:57:10.911 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
17:57:10.950 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
17:57:10.952 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
17:57:10.953 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:11.371 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:11.577 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
17:57:11.781 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
17:57:11.965 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
17:57:12.155 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
17:57:12.342 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
17:57:12.534 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
17:57:12.724 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
17:57:12.916 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
17:57:13.025 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
17:57:13.133 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
17:57:13.220 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
17:57:13.227 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
17:57:13.311 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
17:57:13.311 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:13.312 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:13.313 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
17:57:13.315 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
17:57:13.603 INFO TrancheManager - Finding 4 tranches for 131821 variants
17:57:13.648 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
17:57:13.667 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
17:57:13.667 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]
17:57:13.667 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
17:57:13.689 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
17:57:13.689 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]
17:57:13.689 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
17:57:13.710 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
17:57:13.710 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]
17:57:13.710 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
17:57:13.728 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
17:57:13.728 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]
17:57:13.728 INFO VariantRecalibrator - Writing out recalibration table...
17:57:14.056 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:14 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.07 minutes.
Runtime.totalMemory()=1000341504
17:57:14.082 INFO gatk - Initializing VQSR tests/resetting random number generator
17:57:14.091 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:14.094 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression4529086097856417190.so: /tmp/libgkl_compression4529086097856417190.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:14.094 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:14.097 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression6808012129587436445.so: /tmp/libgkl_compression6808012129587436445.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:14.099 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:14.099 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:14.099 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:14.099 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:14.099 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:14.099 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:14 PM UTC
17:57:14.100 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:14.100 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:14.100 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:14.100 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:14.100 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:14.100 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:14.100 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:14.100 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:14.100 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:14.100 INFO VariantRecalibrator - Requester pays: disabled
17:57:14.100 INFO VariantRecalibrator - Initializing engine
17:57:14.100 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.102 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
17:57:14.102 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.102 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.102 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.111 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.112 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
17:57:14.112 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.112 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.113 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.121 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.122 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.122 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:14.150 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
17:57:14.163 INFO VariantRecalibrator - Done initializing engine
17:57:14.164 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
17:57:14.176 INFO ProgressMeter - Starting traversal
17:57:14.176 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:14.258 INFO ProgressMeter - chr1:6212018 0.0 2791 2042195.1
17:57:14.258 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
17:57:14.258 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
17:57:14.259 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
17:57:14.259 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
17:57:14.259 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
17:57:14.260 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
17:57:14.260 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
17:57:14.261 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:14.305 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:14.333 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
17:57:14.360 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
17:57:14.388 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
17:57:14.415 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
17:57:14.442 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
17:57:14.470 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
17:57:14.497 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
17:57:14.524 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
17:57:14.551 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
17:57:14.579 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
17:57:14.606 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
17:57:14.633 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
17:57:14.633 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
17:57:14.636 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
17:57:14.650 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
17:57:14.650 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:14.650 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:14.651 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
17:57:14.651 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
17:57:14.665 INFO TrancheManager - Finding 4 tranches for 2786 variants
17:57:14.666 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
17:57:14.666 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
17:57:14.666 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]
17:57:14.667 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
17:57:14.667 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
17:57:14.667 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]
17:57:14.667 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
17:57:14.667 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
17:57:14.667 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]
17:57:14.667 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
17:57:14.668 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
17:57:14.668 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]
17:57:14.668 INFO VariantRecalibrator - Writing out recalibration table...
17:57:14.688 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:14 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1000341504
17:57:14.692 INFO gatk - Initializing VQSR tests/resetting random number generator
[October 27, 2025 at 5:57:17 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1000341504
17:57:17.936 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:17.939 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression11989255679106695097.so: /tmp/libgkl_compression11989255679106695097.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:17.939 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:17.943 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression7284890095233701107.so: /tmp/libgkl_compression7284890095233701107.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:17.944 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:17.944 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:17.944 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:17.944 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:17.944 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:17.945 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:17 PM UTC
17:57:17.945 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:17.945 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:17.945 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:17.945 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:17.945 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:17.945 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:17.945 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:17.945 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:17.945 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:17.945 INFO VariantRecalibrator - Requester pays: disabled
17:57:17.945 INFO VariantRecalibrator - Initializing engine
17:57:17.946 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
17:57:17.949 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
17:57:17.950 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
17:57:17.952 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
17:57:17.953 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:17.954 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
17:57:17.955 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:17.955 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:17.955 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:17.958 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:17.958 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:17.959 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:17.969 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
17:57:17.969 INFO VariantRecalibrator - Done initializing engine
17:57:17.970 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
17:57:17.970 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
17:57:17.970 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
17:57:17.971 INFO ProgressMeter - Starting traversal
17:57:17.972 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:19.114 INFO ProgressMeter - 20:9938789 0.0 134919 7088563.9
17:57:19.115 INFO ProgressMeter - Traversal complete. Processed 134919 total variants in 0.0 minutes.
17:57:19.118 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
17:57:19.126 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
17:57:19.132 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
17:57:19.166 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
17:57:19.169 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
17:57:19.169 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:19.576 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:19.662 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.13181
17:57:19.746 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.46782
17:57:19.828 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 9.04961
17:57:19.909 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.04477
17:57:19.991 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01711
17:57:20.072 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.02053
17:57:20.154 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.01194
17:57:20.235 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.01038
17:57:20.317 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.06192
17:57:20.398 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01281
17:57:20.486 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00457
17:57:20.519 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
17:57:20.524 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
17:57:20.650 INFO VariantDataManager - Selected worst 754 scoring variants --> variants with LOD <= -5.0000.
17:57:20.650 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:20.653 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:20.654 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.05287
17:57:20.656 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.02030
17:57:20.657 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.00986
17:57:20.659 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.00749
17:57:20.661 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.00850
17:57:20.662 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01430
17:57:20.664 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02541
17:57:20.666 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.02173
17:57:20.667 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.01024
17:57:20.669 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00479
17:57:20.671 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00245
17:57:20.671 INFO VariantRecalibratorEngine - Convergence after 57 iterations!
17:57:20.674 INFO VariantRecalibratorEngine - Evaluating full set of 134603 variants...
17:57:20.940 INFO TrancheManager - Finding 4 tranches for 134603 variants
17:57:20.993 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
17:57:21.015 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
17:57:21.015 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]
17:57:21.015 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
17:57:21.040 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 649; running score is 0.001
17:57:21.040 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]
17:57:21.040 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
17:57:21.065 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 7924; running score is 0.010
17:57:21.065 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]
17:57:21.065 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
17:57:21.089 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 52632; running score is 0.100
17:57:21.089 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]
17:57:21.089 INFO VariantRecalibrator - Writing out recalibration table...
17:57:21.444 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:21 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.06 minutes.
Runtime.totalMemory()=1000341504
17:57:21.446 INFO gatk - Initializing VQSR tests/resetting random number generator
17:57:21.453 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:21.457 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression15825689011032010518.so: /tmp/libgkl_compression15825689011032010518.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:21.457 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:21.460 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression15363594145282125311.so: /tmp/libgkl_compression15363594145282125311.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:21.462 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:21.462 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:21.462 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:21.462 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:21.462 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:21.462 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:21 PM UTC
17:57:21.463 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:21.463 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:21.463 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:21.463 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:21.463 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:21.463 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:21.463 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:21.463 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:21.463 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:21.463 INFO VariantRecalibrator - Requester pays: disabled
17:57:21.463 INFO VariantRecalibrator - Initializing engine
17:57:21.464 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
17:57:21.466 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
17:57:21.468 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
17:57:21.469 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
17:57:21.471 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
17:57:21.472 INFO VariantRecalibrator - Done initializing engine
17:57:21.472 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
17:57:21.472 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
17:57:21.472 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
17:57:21.473 INFO ProgressMeter - Starting traversal
17:57:21.473 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:22.572 INFO ProgressMeter - 20:9944766 0.0 131821 7196778.9
17:57:22.572 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
17:57:22.575 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
17:57:22.581 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
17:57:22.586 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
17:57:22.614 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
17:57:22.616 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
17:57:22.616 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:23.078 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:23.274 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
17:57:23.469 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
17:57:23.660 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
17:57:23.847 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
17:57:24.033 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
17:57:24.216 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
17:57:24.324 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
17:57:24.432 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
17:57:24.539 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
17:57:24.647 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
17:57:24.733 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
17:57:24.739 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
17:57:24.826 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
17:57:24.827 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:24.828 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:24.829 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
17:57:24.831 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
17:57:25.125 INFO TrancheManager - Finding 12 tranches for 131821 variants
17:57:25.180 INFO TrancheManager - VQSLODTranche threshold 10.00 => selection metric threshold 0.900
17:57:25.213 INFO TrancheManager - Found tranche for 10.000: 0.900 threshold starting with variant 97819; running score is 0.262
17:57:25.213 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=10.0000 known=(29048 @ 2.5026) novel=(4954 @ 2.3633) truthSites(18665 accessible, 13780 called), name=anonymous]
17:57:25.213 INFO TrancheManager - VQSLODTranche threshold 8.00 => selection metric threshold 0.920
17:57:25.241 INFO TrancheManager - Found tranche for 8.000: 0.920 threshold starting with variant 68875; running score is 0.114
17:57:25.241 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=8.0000 known=(44004 @ 2.4829) novel=(18942 @ 2.4147) truthSites(18665 accessible, 16543 called), name=anonymous]
17:57:25.241 INFO TrancheManager - VQSLODTranche threshold 6.00 => selection metric threshold 0.940
17:57:25.264 INFO TrancheManager - Found tranche for 6.000: 0.940 threshold starting with variant 34094; running score is 0.052
17:57:25.265 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=6.0000 known=(52474 @ 2.4242) novel=(45253 @ 2.3994) truthSites(18665 accessible, 17701 called), name=anonymous]
17:57:25.265 INFO TrancheManager - VQSLODTranche threshold 4.00 => selection metric threshold 0.960
17:57:25.288 INFO TrancheManager - Found tranche for 4.000: 0.960 threshold starting with variant 12275; running score is 0.023
17:57:25.288 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=4.0000 known=(56181 @ 2.3913) novel=(63365 @ 2.3212) truthSites(18665 accessible, 18243 called), name=anonymous]
17:57:25.288 INFO TrancheManager - VQSLODTranche threshold 2.00 => selection metric threshold 0.980
17:57:25.311 INFO TrancheManager - Found tranche for 2.000: 0.980 threshold starting with variant 4952; running score is 0.009
17:57:25.311 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=2.0000 known=(57758 @ 2.3573) novel=(69111 @ 2.2722) truthSites(18665 accessible, 18502 called), name=anonymous]
17:57:25.311 INFO TrancheManager - VQSLODTranche threshold 0.00 => selection metric threshold 1.000
17:57:25.335 INFO TrancheManager - Found tranche for 0.000: 1.000 threshold starting with variant 2260; running score is 0.004
17:57:25.335 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=0.0000 known=(58579 @ 2.3306) novel=(70982 @ 2.2511) truthSites(18665 accessible, 18598 called), name=anonymous]
17:57:25.335 INFO TrancheManager - VQSLODTranche threshold -2.00 => selection metric threshold 1.020
17:57:25.358 INFO TrancheManager - Found tranche for -2.000: 1.020 threshold starting with variant 1099; running score is 0.001
17:57:25.358 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-2.0000 known=(59019 @ 2.3111) novel=(71703 @ 2.2372) truthSites(18665 accessible, 18640 called), name=anonymous]
17:57:25.358 INFO TrancheManager - VQSLODTranche threshold -4.00 => selection metric threshold 1.040
17:57:25.382 INFO TrancheManager - Found tranche for -4.000: 1.040 threshold starting with variant 606; running score is 0.001
17:57:25.382 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-4.0000 known=(59205 @ 2.3054) novel=(72010 @ 2.2272) truthSites(18665 accessible, 18648 called), name=anonymous]
17:57:25.382 INFO TrancheManager - VQSLODTranche threshold -6.00 => selection metric threshold 1.060
17:57:25.405 INFO TrancheManager - Found tranche for -6.000: 1.060 threshold starting with variant 429; running score is 0.001
17:57:25.405 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-6.0000 known=(59292 @ 2.3026) novel=(72100 @ 2.2261) truthSites(18665 accessible, 18653 called), name=anonymous]
17:57:25.405 INFO TrancheManager - VQSLODTranche threshold -8.00 => selection metric threshold 1.080
17:57:25.430 INFO TrancheManager - Found tranche for -8.000: 1.080 threshold starting with variant 314; running score is 0.000
17:57:25.430 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-8.0000 known=(59355 @ 2.3009) novel=(72152 @ 2.2247) truthSites(18665 accessible, 18657 called), name=anonymous]
17:57:25.430 INFO TrancheManager - VQSLODTranche threshold -10.00 => selection metric threshold 1.100
17:57:25.453 INFO TrancheManager - Found tranche for -10.000: 1.100 threshold starting with variant 264; running score is 0.000
17:57:25.453 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-10.0000 known=(59372 @ 2.3008) novel=(72185 @ 2.2246) truthSites(18665 accessible, 18658 called), name=anonymous]
17:57:25.453 INFO TrancheManager - VQSLODTranche threshold -12.00 => selection metric threshold 1.120
17:57:25.477 INFO TrancheManager - Found tranche for -12.000: 1.120 threshold starting with variant 211; running score is 0.000
17:57:25.477 INFO TrancheManager - VQSLODTranche is Tranche minVQSLod=-12.0000 known=(59394 @ 2.3004) novel=(72216 @ 2.2244) truthSites(18665 accessible, 18659 called), name=anonymous]
17:57:25.477 INFO VariantRecalibrator - Writing out recalibration table...
17:57:25.820 INFO VariantRecalibrator - Tranches plot will not be generated since we are running in scattered mode
17:57:25.844 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:25 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.07 minutes.
Runtime.totalMemory()=1000341504
17:57:25.871 INFO gatk - Initializing VQSR tests/resetting random number generator
[October 27, 2025 at 5:57:27 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1000341504
17:57:27.515 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:27.518 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression12385359784458578934.so: /tmp/libgkl_compression12385359784458578934.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:27.518 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:27.522 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression11661324173541503213.so: /tmp/libgkl_compression11661324173541503213.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:27.523 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:27.523 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:27.523 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:27.524 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:27.524 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:27.524 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:27 PM UTC
17:57:27.524 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:27.524 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:27.524 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:27.524 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:27.524 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:27.524 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:27.524 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:27.524 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:27.524 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:27.524 INFO VariantRecalibrator - Requester pays: disabled
17:57:27.524 INFO VariantRecalibrator - Initializing engine
17:57:27.525 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.526 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
17:57:27.526 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.526 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.526 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.534 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.535 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
17:57:27.535 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.535 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.536 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.543 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.543 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.544 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:27.570 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
17:57:27.583 INFO VariantRecalibrator - Done initializing engine
17:57:27.583 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
17:57:27.595 INFO ProgressMeter - Starting traversal
17:57:27.595 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:27.680 INFO ProgressMeter - chr1:6212018 0.0 2791 1970117.6
17:57:27.680 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
17:57:27.681 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
17:57:27.681 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
17:57:27.681 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
17:57:27.681 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
17:57:27.682 INFO VariantDataManager - AS_FS: mean = 1.08 standard deviation = 2.43
17:57:27.682 INFO VariantDataManager - AS_MQRankSum: mean = 0.00 standard deviation = 0.01
17:57:27.683 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR, AS_FS, AS_MQRankSum]
17:57:27.683 INFO VariantDataManager - Training with 2769 variants after standard deviation thresholding.
17:57:27.683 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:27.726 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:27.761 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.56007
17:57:27.796 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.67355
17:57:27.830 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 5.08559
17:57:27.865 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.01567
17:57:27.899 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.02021
17:57:27.933 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.01989
17:57:27.967 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.02504
17:57:28.001 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03657
17:57:28.035 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.04057
17:57:28.069 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.08648
17:57:28.103 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.01514
17:57:28.143 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00496
17:57:28.168 INFO VariantRecalibratorEngine - Finished iteration 65. Current change in mixture coefficients = 0.00163
17:57:28.168 INFO VariantRecalibratorEngine - Convergence after 65 iterations!
17:57:28.171 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
17:57:28.193 INFO VariantDataManager - Selected worst 5 scoring variants --> variants with LOD <= -5.0000.
17:57:28.193 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:28.193 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:28.193 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
17:57:28.193 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
17:57:28.209 INFO TrancheManager - Finding 4 tranches for 2786 variants
17:57:28.210 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
17:57:28.210 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
17:57:28.210 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]
17:57:28.210 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
17:57:28.210 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
17:57:28.210 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]
17:57:28.211 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
17:57:28.211 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
17:57:28.211 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]
17:57:28.211 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
17:57:28.211 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
17:57:28.211 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]
17:57:28.211 INFO VariantRecalibrator - Writing out recalibration table...
17:57:28.227 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:28 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1000341504
17:57:28.228 INFO gatk - Initializing VQSR tests/resetting random number generator
[October 27, 2025 at 5:57:31 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=1000341504
[October 27, 2025 at 5:57:31 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1000341504
[October 27, 2025 at 5:57:31 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1000341504
[October 27, 2025 at 5:57:31 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=1000341504
[October 27, 2025 at 5:57:32 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1000341504
[October 27, 2025 at 5:57:34 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.03 minutes.
Runtime.totalMemory()=1000341504
17:57:34.556 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:34.560 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression5723644322642065163.so: /tmp/libgkl_compression5723644322642065163.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:34.560 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:34.563 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression15760666275146882631.so: /tmp/libgkl_compression15760666275146882631.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:34.565 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:34.565 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:34.565 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:34.565 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:34.565 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:34.565 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:34 PM UTC
17:57:34.565 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:34.565 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:34.565 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:34.565 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:34.565 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:34.565 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:34.565 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:34.565 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:34.565 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:34.565 INFO VariantRecalibrator - Requester pays: disabled
17:57:34.565 INFO VariantRecalibrator - Initializing engine
17:57:34.566 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
17:57:34.568 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
17:57:34.570 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
17:57:34.571 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
17:57:34.573 INFO IntervalArgumentCollection - Processing 9000001 bp from intervals
17:57:34.574 INFO VariantRecalibrator - Done initializing engine
17:57:34.574 INFO TrainingSet - Found known track: Known = true Training = false Truth = false Prior = Q10.0
17:57:34.574 INFO TrainingSet - Found truth_training1 track: Known = false Training = true Truth = true Prior = Q15.0
17:57:34.574 INFO TrainingSet - Found truth_training2 track: Known = false Training = true Truth = true Prior = Q12.0
17:57:34.575 INFO ProgressMeter - Starting traversal
17:57:34.575 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:35.666 INFO ProgressMeter - 20:9944766 0.0 131821 7249550.9
17:57:35.666 INFO ProgressMeter - Traversal complete. Processed 131821 total variants in 0.0 minutes.
17:57:35.670 INFO VariantDataManager - QD: mean = 16.58 standard deviation = 5.43
17:57:35.676 INFO VariantDataManager - HaplotypeScore: mean = 0.27 standard deviation = 0.27
17:57:35.682 INFO VariantDataManager - HRun: mean = 0.59 standard deviation = 0.99
17:57:35.713 INFO VariantDataManager - Annotation order is: [QD, HRun, HaplotypeScore]
17:57:35.715 INFO VariantDataManager - Training with 18642 variants after standard deviation thresholding.
17:57:35.716 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:36.190 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:36.406 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.42302
17:57:36.624 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.24203
17:57:36.764 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.15214
17:57:36.870 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.22858
17:57:36.977 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.07799
17:57:37.085 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.04227
17:57:37.193 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00976
17:57:37.301 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.03859
17:57:37.409 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.18953
17:57:37.517 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01049
17:57:37.604 INFO VariantRecalibratorEngine - Convergence after 54 iterations!
17:57:37.610 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
17:57:37.704 INFO VariantDataManager - Selected worst 474 scoring variants --> variants with LOD <= -5.0000.
17:57:37.704 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:37.705 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:37.706 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
17:57:37.708 INFO VariantRecalibratorEngine - Evaluating full set of 131821 variants...
17:57:38.002 INFO TrancheManager - Finding 12 tranches for 131821 variants
17:57:38.064 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
17:57:38.084 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
17:57:38.084 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]
17:57:38.084 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
17:57:38.104 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 381; running score is 0.001
17:57:38.104 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]
17:57:38.104 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
17:57:38.122 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 747; running score is 0.001
17:57:38.122 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]
17:57:38.122 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
17:57:38.139 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 1480; running score is 0.002
17:57:38.139 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]
17:57:38.139 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
17:57:38.156 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 2377; running score is 0.004
17:57:38.156 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]
17:57:38.156 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
17:57:38.173 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 3042; running score is 0.005
17:57:38.173 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]
17:57:38.173 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
17:57:38.188 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 3577; running score is 0.006
17:57:38.188 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]
17:57:38.188 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
17:57:38.205 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 4004; running score is 0.007
17:57:38.205 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]
17:57:38.205 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
17:57:38.221 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 5604; running score is 0.010
17:57:38.221 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]
17:57:38.221 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
17:57:38.238 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 10673; running score is 0.020
17:57:38.239 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]
17:57:38.239 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
17:57:38.256 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 16985; running score is 0.030
17:57:38.256 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]
17:57:38.256 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
17:57:38.272 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 63492; running score is 0.100
17:57:38.273 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]
17:57:38.273 INFO VariantRecalibrator - Writing out recalibration table...
17:57:38.608 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:38 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.07 minutes.
Runtime.totalMemory()=1000341504
17:57:38.634 INFO gatk - Initializing VQSR tests/resetting random number generator
17:57:38.641 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:38.644 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression10825563890163487369.so: /tmp/libgkl_compression10825563890163487369.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:38.644 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/runner/.gradle/caches/modules-2/files-2.1/com.intel.gkl/gkl/0.9.1/e23340ee393a396807581d7af5b835c7fcf10ab3/gkl-0.9.1.jar!/com/intel/gkl/native/libgkl_compression.so
17:57:38.647 WARN NativeLibraryLoader - Unable to load libgkl_compression.so from native/libgkl_compression.so (/tmp/libgkl_compression1647313695380361376.so: /tmp/libgkl_compression1647313695380361376.so: cannot open shared object file: No such file or directory (Possible cause: can't load AMD 64 .so on a AARCH64 platform))
17:57:38.648 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:38.648 INFO VariantRecalibrator - org.broadinstitute.hellbender.tools.walkers.vqsr vUnavailable
17:57:38.648 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
17:57:38.649 INFO VariantRecalibrator - Executing as runner@runnervmrcw8b on Linux v6.11.0-1018-azure aarch64
17:57:38.649 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v17.0.6+10
17:57:38.649 INFO VariantRecalibrator - Start Date/Time: October 27, 2025 at 5:57:38 PM UTC
17:57:38.649 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:38.649 INFO VariantRecalibrator - ------------------------------------------------------------
17:57:38.649 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:57:38.649 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:57:38.649 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:57:38.649 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:57:38.649 INFO VariantRecalibrator - Deflater: JdkDeflater
17:57:38.649 INFO VariantRecalibrator - Inflater: JdkInflater
17:57:38.649 INFO VariantRecalibrator - GCS max retries/reopens: 20
17:57:38.649 INFO VariantRecalibrator - Requester pays: disabled
17:57:38.649 INFO VariantRecalibrator - Initializing engine
17:57:38.649 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.650 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
17:57:38.651 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.651 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.651 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.658 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.659 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
17:57:38.659 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.660 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.660 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.667 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.668 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.668 WARN IntelInflaterFactory - IntelInflater is not supported, using Java.util.zip.Inflater
17:57:38.693 INFO IntervalArgumentCollection - Processing 10000000 bp from intervals
17:57:38.704 INFO VariantRecalibrator - Done initializing engine
17:57:38.705 INFO TrainingSet - Found same track: Known = false Training = true Truth = true Prior = Q15.0
17:57:38.715 INFO ProgressMeter - Starting traversal
17:57:38.715 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
17:57:38.796 INFO ProgressMeter - chr1:6212018 0.0 2791 2093250.0
17:57:38.796 INFO ProgressMeter - Traversal complete. Processed 2791 total variants in 0.0 minutes.
17:57:38.796 INFO VariantDataManager - AS_QD: mean = 20.88 standard deviation = 8.12
17:57:38.796 INFO VariantDataManager - AS_ReadPosRankSum: mean = -0.05 standard deviation = 0.74
17:57:38.796 INFO VariantDataManager - AS_MQ: mean = 59.82 standard deviation = 2.48
17:57:38.797 INFO VariantDataManager - AS_SOR: mean = 0.86 standard deviation = 0.67
17:57:38.798 INFO VariantDataManager - Annotation order is: [AS_QD, AS_ReadPosRankSum, AS_MQ, AS_SOR]
17:57:38.798 INFO VariantDataManager - Training with 2774 variants after standard deviation thresholding.
17:57:38.798 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:38.841 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:38.869 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.12046
17:57:38.897 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.09714
17:57:38.916 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.07781
17:57:38.936 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.05863
17:57:38.955 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01774
17:57:38.975 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00612
17:57:38.994 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00395
17:57:39.013 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.00313
17:57:39.033 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.00276
17:57:39.052 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.00245
17:57:39.072 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00219
17:57:39.091 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00198
17:57:39.091 INFO VariantRecalibratorEngine - Convergence after 60 iterations!
17:57:39.093 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
17:57:39.106 INFO VariantDataManager - Selected worst 6 scoring variants --> variants with LOD <= -5.0000.
17:57:39.106 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
17:57:39.106 INFO VariantRecalibratorEngine - Finished iteration 0.
17:57:39.106 INFO VariantRecalibratorEngine - Convergence after 3 iterations!
17:57:39.106 INFO VariantRecalibratorEngine - Evaluating full set of 2786 variants...
17:57:39.117 INFO TrancheManager - Finding 12 tranches for 2786 variants
17:57:39.118 INFO TrancheManager - TruthSensitivityTranche threshold 100.00 => selection metric threshold 0.000
17:57:39.118 INFO TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000
17:57:39.118 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]
17:57:39.118 INFO TrancheManager - TruthSensitivityTranche threshold 99.95 => selection metric threshold 0.000
17:57:39.118 INFO TrancheManager - Found tranche for 99.950: 0.000 threshold starting with variant 2; running score is 0.001
17:57:39.118 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]
17:57:39.118 INFO TrancheManager - TruthSensitivityTranche threshold 99.90 => selection metric threshold 0.001
17:57:39.118 INFO TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 3; running score is 0.001
17:57:39.118 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]
17:57:39.118 INFO TrancheManager - TruthSensitivityTranche threshold 99.80 => selection metric threshold 0.002
17:57:39.119 INFO TrancheManager - Found tranche for 99.800: 0.002 threshold starting with variant 6; running score is 0.002
17:57:39.119 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]
17:57:39.119 INFO TrancheManager - TruthSensitivityTranche threshold 99.60 => selection metric threshold 0.004
17:57:39.119 INFO TrancheManager - Found tranche for 99.600: 0.004 threshold starting with variant 12; running score is 0.004
17:57:39.119 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]
17:57:39.119 INFO TrancheManager - TruthSensitivityTranche threshold 99.50 => selection metric threshold 0.005
17:57:39.119 INFO TrancheManager - Found tranche for 99.500: 0.005 threshold starting with variant 14; running score is 0.005
17:57:39.119 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]
17:57:39.119 INFO TrancheManager - TruthSensitivityTranche threshold 99.40 => selection metric threshold 0.006
17:57:39.119 INFO TrancheManager - Found tranche for 99.400: 0.006 threshold starting with variant 17; running score is 0.006
17:57:39.119 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]
17:57:39.119 INFO TrancheManager - TruthSensitivityTranche threshold 99.30 => selection metric threshold 0.007
17:57:39.120 INFO TrancheManager - Found tranche for 99.300: 0.007 threshold starting with variant 20; running score is 0.007
17:57:39.120 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]
17:57:39.120 INFO TrancheManager - TruthSensitivityTranche threshold 99.00 => selection metric threshold 0.010
17:57:39.120 INFO TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 28; running score is 0.010
17:57:39.120 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]
17:57:39.120 INFO TrancheManager - TruthSensitivityTranche threshold 98.00 => selection metric threshold 0.020
17:57:39.120 INFO TrancheManager - Found tranche for 98.000: 0.020 threshold starting with variant 56; running score is 0.020
17:57:39.120 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]
17:57:39.120 INFO TrancheManager - TruthSensitivityTranche threshold 97.00 => selection metric threshold 0.030
17:57:39.120 INFO TrancheManager - Found tranche for 97.000: 0.030 threshold starting with variant 84; running score is 0.030
17:57:39.121 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]
17:57:39.121 INFO TrancheManager - TruthSensitivityTranche threshold 90.00 => selection metric threshold 0.100
17:57:39.121 INFO TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 279; running score is 0.100
17:57:39.121 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]
17:57:39.121 INFO VariantRecalibrator - Writing out recalibration table...
17:57:39.134 INFO VariantRecalibrator - Shutting down engine
[October 27, 2025 at 5:57:39 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=1000341504
[October 27, 2025 at 5:58:48 PM UTC] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 0.02 minutes.
Runtime.totalMemory()=769654784