On Monday and Tuesday, November 12-13, the communications team will be out of the office for a U.S. federal holiday and a team event. We will be back in action on November 14th and apologize for any inconvenience this may cause. Thank you for using the forum.

GATk 3.6 / VariantRecalibrator is getting slower and slower.

lindenblindenb FranceMember ✭✭

Hi GATK team, I'm running VariantRecalibrator (v 3.6) on SNPs on ~300 Sample WGS.

java  -Xmx5g -Djava.io.tmpdir=... -jar GenomeAnalysisTK.jar
-T VariantRecalibrator -R all_chr.fasta
-input MergedVCF.vcf.gz
--disable_auto_index_creation_and_locking_when_reading_rods 
-resource:hapmap,known=false,training=true,truth=true,prior=15.0 hg19mt_all_chr_hapmap_3.3.vcf
-resource:omni,known=false,training=true,truth=true,prior=12.0 hg19mt_all_chr_1000G_omni2.5.vcf
-resource:1000G,known=false,training=true,truth=false,prior=10.0 hg19mt_all_chr_1000G_phase1.snps.high_confidence.vcf  -resource:dbsnp,known=true,training=false,truth=false,prior=2.0 hg19mt_all_chr_dbsnp-142.vcf
--unsafe ALLOW_SEQ_DICT_INCOMPATIBILITY
-an DP  -an QD  -an FS  -an SOR  -an MQ  -an MQRankSum  -an ReadPosRankSum -an InbreedingCoeff -mode SNP
-tranche 100.0 -tranche 99.9 -tranche 99.0 -tranche 90.0 
-recalFile snp.recal  -tranchesFile snp.tranches  -rscriptFile  snp_plots.R

(for the example below I've also used from '-L chr1' to '-L chr9' to re-run my problem)

I'm using ALLOW_SEQ_DICT_INCOMPATIBILITY because all_chr.fasta contains some extra contigs (GL*...., NC_007605 ) at the end that are not present in the resources. So i've got the following warnings:

WARN  09:11:15,983 SequenceDictionaryUtils - Input files dbsnp and reference have incompatible contigs. Please see https://www.broadinstitute.org/gatk/guide/article?id=63for more information. Error details: Found contigs with the same name but different lengths or MD5s:
  contig  dbsnp is named chrMT with length 16571
  contig  reference is named chrMT with length 16569 and MD5 c68f52674c9fb33aef52dcf399755519.
  dbsnp contigs = [chr1, chr2, chr3, chr4, chr5, chr6, chr7, chr8, chr9, chr10, chr11, chr12, chr13, chr14, chr15, chr16, chr17, chr18, chr19, chr20, chr21, chr22, chrX, chrY, chrMT]
  reference contigs = [chr1, chr2, chr3, chr4, chr5, chr6, chr7, chr8, chr9, chr10, chr11, chr12, chr13, chr14, chr15, chr16, chr17, chr18, chr19, chr20, chr21, chr22, chrX, chrY, chrMT, GL000207.1, GL000226.1, GL000229.1, GL000231.1, GL000210.1, GL000239.1, GL000235.1, GL000201.1, GL000247.1, GL000245.1, GL000197.1, GL000203.1, GL000246.1, GL000249.1, GL000196.1, GL000248.1, GL000244.1, GL000238.1, GL000202.1, GL000234.1, GL000232.1, GL000206.1, GL000240.1, GL000236.1, GL000241.1, GL000243.1, GL000242.1, GL000230.1, GL000237.1, GL000233.1, GL000204.1, GL000198.1, GL000208.1, GL000191.1, GL000227.1, GL000228.1, GL000214.1, GL000221.1, GL000209.1, GL000218.1, GL000220.1, GL000213.1, GL000211.1, GL000199.1, GL000217.1, GL000216.1, GL000215.1, GL000205.1, GL000219.1, GL000224.1, GL000223.1, GL000195.1, GL000212.1, GL000222.1, GL000200.1, GL000193.1, GL000194.1, GL000225.1, GL000192.1, NC_007605, hs37d5] 

At first, everything seems fine:

INFO  09:11:46,215 ProgressMeter -    chr1:9006242    336937.0    30.0 s      89.0 s        0.5%    93.3 m      92.8 m 
INFO  09:12:16,216 ProgressMeter -   chr1:20194760    671510.0    60.0 s      89.0 s        1.2%    83.2 m      82.2 m 
INFO  09:12:46,217 ProgressMeter -   chr1:33094511   1036129.0    90.0 s      86.0 s        2.0%    76.2 m      74.7 m 
INFO  09:13:16,218 ProgressMeter -   chr1:47059272   1413282.0   120.0 s      85.0 s        2.8%    71.4 m      69.4 m 
INFO  09:13:46,219 ProgressMeter -   chr1:61539042   1767575.0     2.5 m      84.0 s        3.7%    68.3 m      65.8 m 
INFO  09:14:16,224 ProgressMeter -   chr1:75472564   2122771.0     3.0 m      84.0 s        4.5%    66.8 m      63.8 m 
INFO  09:14:46,434 ProgressMeter -   chr1:88730642   2458066.0     3.5 m      85.0 s        5.3%    66.3 m      62.8 m 
INFO  09:15:16,452 ProgressMeter -  chr1:102443884   2804894.0     4.0 m      85.0 s        6.1%    65.6 m      61.6 m 
(...)

and then, in chr8, things are getting slower...

INFO  10:28:28,034 ProgressMeter -   chr8:36475208   3.9400101E7    77.2 m     117.0 s       85.1%    90.7 m      13.6 m 
INFO  10:28:58,035 ProgressMeter -   chr8:48680458   3.9671788E7    77.7 m     117.0 s       85.8%    90.6 m      12.9 m 
INFO  10:29:28,292 ProgressMeter -   chr8:58522718   3.9938608E7    78.2 m     117.0 s       86.4%    90.5 m      12.3 m 
INFO  10:29:58,293 ProgressMeter -   chr8:69058109   4.022234E7    78.7 m     117.0 s       87.0%    90.5 m      11.8 m 
INFO  10:30:28,341 ProgressMeter -   chr8:79398637   4.0483139E7    79.2 m     117.0 s       87.6%    90.4 m      11.2 m 
INFO  10:31:08,342 ProgressMeter -   chr8:94000024   4.0864344E7    79.9 m     117.0 s       88.5%    90.3 m      10.4 m 
INFO  10:33:34,514 ProgressMeter -   chr8:95214891   4.0888881E7    82.3 m     120.0 s       88.6%    92.9 m      10.6 m 
INFO  10:35:11,038 ProgressMeter -   chr8:95713832   4.0888881E7    83.9 m       2.1 m       88.6%    94.7 m      10.8 m 
INFO  10:36:42,040 ProgressMeter -   chr8:96194278   4.0915453E7    85.4 m       2.1 m       88.6%    96.4 m      11.0 m 
INFO  10:38:11,485 ProgressMeter -   chr8:96648354   4.0915453E7    86.9 m       2.1 m       88.6%    98.1 m      11.1 m 
INFO  10:39:48,389 ProgressMeter -   chr8:97153122   4.0942281E7    88.5 m       2.2 m       88.7%    99.8 m      11.3 m 
INFO  10:41:42,570 ProgressMeter -   chr8:97697055   4.0942281E7    90.4 m       2.2 m       88.7%   102.0 m      11.5 m 
INFO  10:43:26,436 ProgressMeter -   chr8:98308009   4.0966796E7    92.2 m       2.2 m       88.7%   103.9 m      11.7 m 
INFO  10:45:16,039 ProgressMeter -   chr8:98785880   4.0966796E7    94.0 m       2.3 m       88.8%   105.9 m      11.9 m 
INFO  10:47:01,519 ProgressMeter -   chr8:99223963   4.0993347E7    95.8 m       2.3 m       88.8%   107.8 m      12.1 m 

and slower....

INFO  13:44:41,720 ProgressMeter -  chr8:145271586   4.2288449E7     4.6 h       6.5 m       91.5%     5.0 h      25.3 m 
INFO  13:46:29,051 ProgressMeter -  chr8:145818267   4.2288449E7     4.6 h       6.5 m       91.6%     5.0 h      25.4 m 
INFO  13:48:14,370 ProgressMeter -  chr8:146189957   4.2322367E7     4.6 h       6.5 m       91.6%     5.0 h      25.4 m 
INFO  13:50:06,807 ProgressMeter -     chr9:192471   4.2334771E7     4.6 h       6.6 m       91.6%     5.1 h      25.5 m 
INFO  13:51:54,196 ProgressMeter -     chr9:491976   4.2334771E7     4.7 h       6.6 m       91.6%     5.1 h      25.6 m 
INFO  13:53:39,407 ProgressMeter -     chr9:791074   4.2334771E7     4.7 h       6.7 m       91.6%     5.1 h      25.7 m 
INFO  13:55:32,305 ProgressMeter -    chr9:1068250   4.2374371E7     4.7 h       6.7 m       91.7%     5.2 h      25.9 m 
INFO  13:57:20,202 ProgressMeter -    chr9:1394666   4.2374371E7     4.8 h       6.8 m       91.7%     5.2 h      26.0 m 
INFO  13:59:08,302 ProgressMeter -    chr9:1718894   4.2374371E7     4.8 h       6.8 m       91.7%     5.2 h      26.1 m 
INFO  14:00:54,688 ProgressMeter -    chr9:2051066   4.2411529E7     4.8 h       6.8 m       91.7%     5.3 h      26.2 m 
INFO  14:02:40,880 ProgressMeter -    chr9:2401865   4.2411529E7     4.9 h       6.9 m       91.7%     5.3 h      26.2 m 

etc...

I've not used the -L option yesterday; I don't remember what was the name of the contig but the expected total time was more than one day and I've killed the job. (My cluster kills the jobs after 24H00..)

Do you have any idea about this problem ?

Thanks !
Pierre

Issue · Github
by Sheila

Issue Number
1596
State
closed
Last Updated
Assignee
Array
Milestone
Array
Closed By
vdauwera

Best Answer

Answers

  • lindenblindenb FranceMember ✭✭
    edited January 2017

    and 3 hours later....

    INFO  16:37:11,694 ProgressMeter -   chr9:33555516   4.3386329E7     7.4 h      10.3 m       93.6%     7.9 h      30.5 m 
    INFO  16:39:03,234 ProgressMeter -   chr9:33952515   4.3386329E7     7.5 h      10.3 m       93.6%     8.0 h      30.5 m 
    INFO  16:40:54,756 ProgressMeter -   chr9:34296211   4.3414917E7     7.5 h      10.4 m       93.6%     8.0 h      30.6 m 
    INFO  16:42:45,999 ProgressMeter -   chr9:34780288   4.3414917E7     7.5 h      10.4 m       93.7%     8.0 h      30.5 m 
    INFO  16:44:36,354 ProgressMeter -   chr9:35254949   4.3440699E7     7.6 h      10.4 m       93.7%     8.1 h      30.5 m 
    INFO  16:46:26,726 ProgressMeter -   chr9:35821173   4.3440699E7     7.6 h      10.5 m       93.7%     8.1 h      30.5 m 
    INFO  16:48:16,864 ProgressMeter -   chr9:36246557   4.3466134E7     7.6 h      10.5 m       93.8%     8.1 h      30.4 m 
    INFO  16:50:05,885 ProgressMeter -   chr9:36654211   4.3466134E7     7.6 h      10.6 m       93.8%     8.2 h      30.4 m 
    INFO  16:52:02,126 ProgressMeter -   chr9:37071372   4.3494288E7     7.7 h      10.6 m       93.8%     8.2 h      30.4 m 
    INFO  16:53:53,075 ProgressMeter -   chr9:37533874   4.3494288E7     7.7 h      10.6 m       93.8%     8.2 h      30.4 m 
    INFO  16:55:49,365 ProgressMeter -   chr9:37945826   4.3494288E7     7.7 h      10.7 m       93.9%     8.2 h      30.4 m 
    INFO  16:57:41,144 ProgressMeter -   chr9:38359456   4.3520601E7     7.8 h      10.7 m       93.9%     8.3 h      30.4 m 
    INFO  16:59:30,805 ProgressMeter -   chr9:38726397   4.3520601E7     7.8 h      10.8 m       93.9%     8.3 h      30.4 m 
    INFO  17:01:20,933 ProgressMeter -   chr9:39057354   4.3547082E7     7.8 h      10.8 m       93.9%     8.3 h      30.4 m 
    INFO  17:03:16,909 ProgressMeter -   chr9:40034468   4.3557896E7     7.9 h      10.8 m       94.0%     8.4 h      30.2 m 
    
Sign In or Register to comment.