VariantRecalibrator throwing VariantRecalibratorEngine - Evaluate datum returned a NaN warning then crashing with empty tranches file.
I'm running a batch of 250 exomes.
It crashes with the error below and and produces an empty tranches file.
I don't *think* there's anything special about the samples in this batch but the other 49 ran without issue or this error using this exact command.
java -version
openjdk version "1.8.0_252"
I've not tried the latest version of the tools because I'm near the end of processing a large dataset with GATK v4.1.4.0 and I'm trying to keep everything as homogenous as possible.
Can you please provide
a) GATK version used
v4.1.4.0
b) Exact GATK commands used
/hades/Software/NGS_Software/gatk-4.1.4.0/gatk --java-options "-Xmx20g" VariantRecalibrator \
-R /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_Homo_sapiens_assembly38.fasta \
-V section50.norm.vcf.gz \
--resource:hapmap,known=false,training=true,truth=true,prior=15.0 /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_hapmap_3.3.hg38.vcf.gz \
--resource:omni,known=false,training=true,truth=false,prior=12.0 /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_1000G_omni2.5.hg38.vcf.gz \
--resource:1000G,known=false,training=true,truth=false,prior=10.0 /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_1000G_phase1.snps.high_confidence.hg38.vcf.gz \
--resource:dbsnp,known=true,training=false,truth=false,prior=2.0 /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_Homo_sapiens_assembly38.dbsnp138.vcf \
-an QD -an MQ -an MQRankSum -an ReadPosRankSum -an FS -an SOR \
-mode SNP \
-O section50.norm.vcf.gz.output.recal \
--tranches-file section50.norm.vcf.gz.output.tranches \
--rscript-file section50.norm.vcf.gz.output.plots.R
c) The entire error log if applicable.
Running:
java -Dsamjdk.use_async_io_read_samtools=false -Dsamjdk.use_async_io_write_samtools=true -Dsamjdk.use_async_io_write_tribble=false -Dsamjdk.compression_level=2 -Xmx20g -jar /hades/Software/NGS_Software/gatk-4.1.4.0/gatk-package-4.1.4.0-local.jar VariantRecalibrator -R /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_Homo_sapiens_assembly38.fasta -V section50.norm.vcf.gz --resource:hapmap,known=false,training=true,truth=true,prior=15.0 /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_hapmap_3.3.hg38.vcf.gz --resource:omni,known=false,training=true,truth=false,prior=12.0 /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_1000G_omni2.5.hg38.vcf.gz --resource:1000G,known=false,training=true,truth=false,prior=10.0 /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_1000G_phase1.snps.high_confidence.hg38.vcf.gz --resource:dbsnp,known=true,training=false,truth=false,prior=2.0 /hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_Homo_sapiens_assembly38.dbsnp138.vcf -an QD -an MQ -an MQRankSum -an ReadPosRankSum -an FS -an SOR -mode SNP -O section50.norm.vcf.gz.output.recal --tranches-file section50.norm.vcf.gz.output.tranches --rscript-file section50.norm.vcf.gz.output.plots.R
04:18:26.698 INFO NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/hades/Software/NGS_Software/gatk-4.1.4.0/gatk-package-4.1.4.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
May 28, 2020 4:18:27 AM shaded.cloud_nio.com.google.auth.oauth2.ComputeEngineCredentials runningOnComputeEngine
INFO: Failed to detect whether we are running on Google Compute Engine.
04:18:27.328 INFO VariantRecalibrator - ------------------------------------------------------------
04:18:27.328 INFO VariantRecalibrator - The Genome Analysis Toolkit (GATK) v4.1.4.0
04:18:27.329 INFO VariantRecalibrator - For support and documentation go to https://software.broadinstitute.org/gatk/
04:18:27.329 INFO VariantRecalibrator - Executing as hades@hades-compute-vm-01-03 on Linux v4.4.0-177-generic amd64
04:18:27.329 INFO VariantRecalibrator - Java runtime: OpenJDK 64-Bit Server VM v1.8.0_252-8u252-b09-1~16.04-b09
04:18:27.329 INFO VariantRecalibrator - Start Date/Time: 28 May 2020 04:18:26 BST
04:18:27.330 INFO VariantRecalibrator - ------------------------------------------------------------
04:18:27.330 INFO VariantRecalibrator - ------------------------------------------------------------
04:18:27.331 INFO VariantRecalibrator - HTSJDK Version: 2.20.3
04:18:27.331 INFO VariantRecalibrator - Picard Version: 2.21.1
04:18:27.331 INFO VariantRecalibrator - HTSJDK Defaults.COMPRESSION_LEVEL : 2
04:18:27.331 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
04:18:27.331 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
04:18:27.331 INFO VariantRecalibrator - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
04:18:27.332 INFO VariantRecalibrator - Deflater: IntelDeflater
04:18:27.332 INFO VariantRecalibrator - Inflater: IntelInflater
04:18:27.332 INFO VariantRecalibrator - GCS max retries/reopens: 20
04:18:27.332 INFO VariantRecalibrator - Requester pays: disabled
04:18:27.332 INFO VariantRecalibrator - Initializing engine
04:18:28.266 INFO FeatureManager - Using codec VCFCodec to read file file:///hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_hapmap_3.3.hg38.vcf.gz
04:18:28.639 INFO FeatureManager - Using codec VCFCodec to read file file:///hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_1000G_omni2.5.hg38.vcf.gz
04:18:28.955 INFO FeatureManager - Using codec VCFCodec to read file file:///hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_1000G_phase1.snps.high_confidence.hg38.vcf.gz
04:18:29.196 INFO FeatureManager - Using codec VCFCodec to read file file:///hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_Homo_sapiens_assembly38.dbsnp138.vcf
04:18:29.614 INFO FeatureManager - Using codec VCFCodec to read file file:///mnt/qsg-results/inprogress/section50.norm.vcf.gz
04:18:30.320 INFO VariantRecalibrator - Done initializing engine
04:18:30.325 INFO TrainingSet - Found hapmap track: Known = false Training = true Truth = true Prior = Q15.0
04:18:30.325 INFO TrainingSet - Found omni track: Known = false Training = true Truth = false Prior = Q12.0
04:18:30.325 INFO TrainingSet - Found 1000G track: Known = false Training = true Truth = false Prior = Q10.0
04:18:30.325 INFO TrainingSet - Found dbsnp track: Known = true Training = false Truth = false Prior = Q2.0
04:18:30.375 WARN GATKVariantContextUtils - Can't determine output variant file format from output file extension "recal". Defaulting to VCF.
04:18:30.422 INFO ProgressMeter - Starting traversal
04:18:30.422 INFO ProgressMeter - Current Locus Elapsed Minutes Variants Processed Variants/Minute
04:18:40.445 INFO ProgressMeter - chr1:35189124 0.2 18000 107762.9
04:18:50.943 INFO ProgressMeter - chr1:77949039 0.3 29000 84791.2
04:19:01.360 INFO ProgressMeter - chr1:155031706 0.5 43000 83395.3
04:19:12.407 INFO ProgressMeter - chr1:200038802 0.7 55000 78599.5
04:19:22.510 INFO ProgressMeter - chr1:236183924 0.9 67000 77181.5
04:19:32.747 INFO ProgressMeter - chr2:30562305 1.0 77000 74128.7
04:19:43.037 INFO ProgressMeter - chr2:73490529 1.2 86000 71060.7
04:19:54.493 INFO ProgressMeter - chr2:135846068 1.4 98000 69941.7
04:20:05.307 INFO ProgressMeter - chr2:186486293 1.6 107000 67660.9
04:20:16.267 INFO ProgressMeter - chr2:231463366 1.8 118000 66890.3
04:20:27.702 INFO ProgressMeter - chr3:32526653 2.0 129000 65995.9
04:20:38.813 INFO ProgressMeter - chr3:75738325 2.1 142000 66360.3
04:20:48.874 INFO ProgressMeter - chr3:128901172 2.3 150000 65004.9
04:20:59.175 INFO ProgressMeter - chr3:179203851 2.5 158000 63730.2
04:21:09.708 INFO ProgressMeter - chr4:8618548 2.7 169000 63659.5
04:21:19.754 INFO ProgressMeter - chr4:70197830 2.8 177000 62717.4
04:21:29.756 INFO ProgressMeter - chr4:119318082 3.0 186000 62230.3
04:21:39.895 INFO ProgressMeter - chr4:184731070 3.2 193000 61117.2
04:21:50.713 INFO ProgressMeter - chr5:43644340 3.3 201000 60212.7
04:22:00.946 INFO ProgressMeter - chr5:102913842 3.5 209000 59565.9
04:22:11.383 INFO ProgressMeter - chr5:161336780 3.7 222000 60282.4
04:22:21.891 INFO ProgressMeter - chr6:32521815 3.9 234000 60656.1
04:22:32.350 INFO ProgressMeter - chr6:89146731 4.0 246000 61010.1
04:22:42.531 INFO ProgressMeter - chr6:152148240 4.2 256000 60926.0
04:22:52.962 INFO ProgressMeter - chr7:31084629 4.4 269000 61476.6
04:23:03.005 INFO ProgressMeter - chr7:100775654 4.5 282000 62072.8
04:23:13.127 INFO ProgressMeter - chr7:152660792 4.7 295000 62609.7
04:23:23.828 INFO ProgressMeter - chr8:30106935 4.9 306000 62575.8
04:23:34.404 INFO ProgressMeter - chr8:93788033 5.1 314000 61977.6
04:23:44.826 INFO ProgressMeter - chr9:2717671 5.2 325000 62022.1
04:23:55.749 INFO ProgressMeter - chr9:81620883 5.4 335000 61784.2
04:24:06.398 INFO ProgressMeter - chr9:127771082 5.6 346000 61790.3
04:24:17.592 INFO ProgressMeter - chr10:24473134 5.8 361000 62390.4
04:24:28.125 INFO ProgressMeter - chr10:80280296 6.0 372000 62398.1
04:24:39.177 INFO ProgressMeter - chr10:132202703 6.1 385000 62643.4
04:24:49.475 INFO ProgressMeter - chr11:33027795 6.3 398000 62999.6
04:24:59.959 INFO ProgressMeter - chr11:73395480 6.5 412000 63460.1
04:25:10.297 INFO ProgressMeter - chr11:118498336 6.7 422000 63319.8
04:25:20.982 INFO ProgressMeter - chr12:20572054 6.8 435000 63571.7
04:25:31.774 INFO ProgressMeter - chr12:70656914 7.0 450000 64079.6
04:25:41.791 INFO ProgressMeter - chr12:112200478 7.2 459000 63843.4
04:25:52.491 INFO ProgressMeter - chr13:32443021 7.4 470000 63790.9
04:26:02.938 INFO ProgressMeter - chr13:101229665 7.5 477000 63246.5
04:26:13.864 INFO ProgressMeter - chr14:59944539 7.7 490000 63438.5
04:26:24.283 INFO ProgressMeter - chr14:103110240 7.9 502000 63563.1
04:26:35.510 INFO ProgressMeter - chr15:58852000 8.1 515000 63699.9
04:26:45.999 INFO ProgressMeter - chr15:99387096 8.3 528000 63925.6
04:26:56.893 INFO ProgressMeter - chr16:52463827 8.4 547000 64801.3
04:27:06.975 INFO ProgressMeter - chr17:7915877 8.6 569000 66092.0
04:27:17.035 INFO ProgressMeter - chr17:60011286 8.8 588000 66994.3
04:27:27.981 INFO ProgressMeter - chr18:13671977 9.0 605000 67527.5
04:27:38.060 INFO ProgressMeter - chr18:63484741 9.1 612000 67051.7
04:27:48.151 INFO ProgressMeter - chr19:17210358 9.3 633000 68097.7
04:27:58.567 INFO ProgressMeter - chr19:51705024 9.5 654000 69067.0
04:28:08.790 INFO ProgressMeter - chr20:33490135 9.6 667000 69194.8
04:28:19.541 INFO ProgressMeter - chr21:15864158 9.8 679000 69154.2
04:28:30.075 INFO ProgressMeter - chr22:29661462 10.0 695000 69540.3
04:28:41.358 INFO ProgressMeter - chrX:38803851 10.2 710000 69729.1
04:28:51.851 INFO ProgressMeter - chrX:136353331 10.4 719000 69420.8
04:28:55.279 INFO ProgressMeter - chrY:11369085 10.4 722446 69370.7
04:28:55.280 INFO ProgressMeter - Traversal complete. Processed 722446 total variants in 10.4 minutes.
04:28:55.408 INFO VariantDataManager - QD: mean = 19.42 standard deviation = 6.70
04:28:55.535 INFO VariantDataManager - MQ: mean = 28.87 standard deviation = 22.90
04:28:55.667 INFO VariantDataManager - MQRankSum: mean = -0.00 standard deviation = 0.12
04:28:55.775 INFO VariantDataManager - ReadPosRankSum: mean = 0.13 standard deviation = 0.63
04:28:55.873 INFO VariantDataManager - FS: mean = 1.87 standard deviation = 3.56
04:28:55.954 INFO VariantDataManager - SOR: mean = 0.95 standard deviation = 0.72
04:28:56.830 INFO VariantDataManager - Annotation order is: [MQ, QD, FS, SOR, MQRankSum, ReadPosRankSum]
04:28:56.907 INFO VariantDataManager - Training with 352569 variants after standard deviation thresholding.
04:28:56.942 INFO GaussianMixtureModel - Initializing model with 100 k-means iterations...
04:29:28.261 INFO VariantRecalibratorEngine - Finished iteration 0.
04:29:39.449 INFO VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 1.30780
04:29:52.733 INFO VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.23266
04:30:03.211 INFO VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.14753
04:30:13.069 INFO VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.13172
04:30:23.015 INFO VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.08243
04:30:32.988 INFO VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.05588
04:30:43.235 INFO VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.06030
04:30:54.651 INFO VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.06568
04:31:05.891 INFO VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.07059
04:31:16.614 INFO VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.07777
04:31:27.311 INFO VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.09113
04:31:37.605 INFO VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.14170
04:31:48.482 INFO VariantRecalibratorEngine - Finished iteration 65. Current change in mixture coefficients = 0.59233
04:32:00.008 INFO VariantRecalibratorEngine - Finished iteration 70. Current change in mixture coefficients = 0.00213
04:32:02.064 INFO VariantRecalibratorEngine - Convergence after 71 iterations!
04:32:03.366 INFO VariantRecalibratorEngine - Evaluating full set of 598837 variants...
04:32:03.366 WARN VariantRecalibratorEngine - Evaluate datum returned a NaN.
04:32:03.422 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.0000.
04:32:03.450 INFO VariantRecalibrator - Shutting down engine
[28 May 2020 04:32:03 BST] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 13.61 minutes.
Runtime.totalMemory()=7133462528
java.lang.IllegalArgumentException: No data found.
at org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibratorEngine.generateModel(VariantRecalibratorEngine.java:34)
at org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator.onTraversalSuccess(VariantRecalibrator.java:655)
at org.broadinstitute.hellbender.engine.GATKTool.doWork(GATKTool.java:1050)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.runTool(CommandLineProgram.java:139)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.instanceMainPostParseArgs(CommandLineProgram.java:191)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.instanceMain(CommandLineProgram.java:210)
at org.broadinstitute.hellbender.Main.runCommandLineProgram(Main.java:163)
at org.broadinstitute.hellbender.Main.mainEntry(Main.java:206)
at org.broadinstitute.hellbender.Main.main(Main.java:292)
-
Trying to rule out various possibilities I removed a few outlier samples that I thought might be the issue with extremely low reads but it had no effect and I continued to get the same error.
This is the end of the log with "debug" level verbosity.
Bizarely the tool seems to be getting a Cache hit rate of 0.00%16:06:28.731 INFO VariantRecalibratorEngine - Convergence after 71 iterations!
16:06:30.208 INFO VariantRecalibratorEngine - Evaluating full set of 598837 variants...
16:06:30.208 WARN VariantRecalibratorEngine - Evaluate datum returned a NaN.
16:06:30.250 INFO VariantDataManager - Selected worst 0 scoring variants --> variants with LOD <= -5.0000.
16:06:30.303 INFO VariantRecalibrator - Shutting down engine
16:06:30.307 DEBUG FeatureDataSource - Cache statistics for FeatureInput hapmap:/hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_hapmap_3.3.hg38.vcf.gz:
16:06:30.307 DEBUG FeatureCache - Cache hit rate was 97.54% (584103 out of 598837 total queries)
16:06:30.308 DEBUG FeatureDataSource - Cache statistics for FeatureInput omni:/hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_1000G_omni2.5.hg38.vcf.gz:
16:06:30.308 DEBUG FeatureCache - Cache hit rate was 97.54% (584103 out of 598837 total queries)
16:06:30.308 DEBUG FeatureDataSource - Cache statistics for FeatureInput 1000G:/hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_1000G_phase1.snps.high_confidence.hg38.vcf.gz:
16:06:30.308 DEBUG FeatureCache - Cache hit rate was 97.54% (584103 out of 598837 total queries)
16:06:30.308 DEBUG FeatureDataSource - Cache statistics for FeatureInput dbsnp:/hades/dmurphy/bwapipeline/ref/gatkresourcebundle/resources_broad_hg38_v0_Homo_sapiens_assembly38.dbsnp138.vcf:
16:06:30.309 DEBUG FeatureCache - Cache hit rate was 97.54% (584103 out of 598837 total queries)
16:06:30.309 DEBUG FeatureDataSource - Cache statistics for FeatureInput /mnt/qsg-results/inprogress/section_50_extract.norm.vcf.gz:
16:06:30.309 DEBUG FeatureCache - Cache hit rate was 0.00% (0 out of 0 total queries)
16:06:30.311 DEBUG FeatureDataSource - Cache statistics for FeatureInput /mnt/qsg-results/inprogress/section_50_extract.norm.vcf.gz:
16:06:30.311 DEBUG FeatureCache - Cache hit rate was 0.00% (0 out of 0 total queries)
[02 June 2020 16:06:30 BST] org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator done. Elapsed time: 17.92 minutes.
Runtime.totalMemory()=5602017280
java.lang.IllegalArgumentException: No data found.
at org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibratorEngine.generateModel(VariantRecalibratorEngine.java:34)
at org.broadinstitute.hellbender.tools.walkers.vqsr.VariantRecalibrator.onTraversalSuccess(VariantRecalibrator.java:655)
at org.broadinstitute.hellbender.engine.GATKTool.doWork(GATKTool.java:1050)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.runTool(CommandLineProgram.java:139)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.instanceMainPostParseArgs(CommandLineProgram.java:191)
at org.broadinstitute.hellbender.cmdline.CommandLineProgram.instanceMain(CommandLineProgram.java:210)
at org.broadinstitute.hellbender.Main.runCommandLineProgram(Main.java:163)
at org.broadinstitute.hellbender.Main.mainEntry(Main.java:206)
at org.broadinstitute.hellbender.Main.main(Main.java:292) -
Hi,
The reason you see this issue is because VariantRecalibrator is unable to create a negative model. Try to reduce number of gaussian. Decreases in increments of 1 or 2. Reducing gaussian will solve that problem. Use this argument to change the default value (8) --max-gaussians
Please sign in to leave a comment.
2 comments