INFO 15:41:04,869 HelpFormatter - -------------------------------------------------------------------------------- INFO 15:41:04,871 HelpFormatter - The Genome Analysis Toolkit (GATK) v3.1-1-g07a4bf8, Compiled 2014/03/18 06:09:21 INFO 15:41:04,871 HelpFormatter - Copyright (c) 2010 The Broad Institute INFO 15:41:04,871 HelpFormatter - For support and documentation go to http://www.broadinstitute.org/gatk INFO 15:41:04,875 HelpFormatter - Program Args: -nt 8 -T VariantRecalibrator -R ucsc.hg19.fasta -input Measles_Genotyped_1000bp_capture_Gvcf.vcf -recalFile Measles_1000bp_4.recal -tranchesFile Measles_1000bp_4.tranches -resource:hapmap,known=false,training=true,truth=true,prior=15.0 hapmap_3.3.hg19.vcf -resource:omni,known=false,training=true,truth=true,prior=12.0 1000G_omni2.5.hg19.vcf -resource:1000G,known=false,training=true,truth=false,prior=10.0 1000G_phase1.snps.high_confidence.hg19.vcf -resource:dbsnp,known=true,training=false,truth=false,prior=2.0 dbsnp_137.hg19.vcf -an QD -an MQ -an MQRankSum -an ReadPosRankSum -an FS -an InbreedingCoeff -mode SNP -tranche 100.0 -tranche 99.9 -tranche 99.0 -tranche 97.5 -tranche 95.0 -tranche 92.5 -tranche 90.0 -tranche 85.0 -rscriptFile recalibrate_SNP_plots2_1000bp_4.R INFO 15:41:04,884 HelpFormatter - Executing as crojo@c559-303.stampede.tacc.utexas.edu on Linux 2.6.32-358.el6.x86_64 amd64; Java HotSpot(TM) 64-Bit Server VM 1.7.0_45-b18. INFO 15:41:04,884 HelpFormatter - Date/Time: 2014/07/02 15:41:04 INFO 15:41:04,884 HelpFormatter - -------------------------------------------------------------------------------- INFO 15:41:04,884 HelpFormatter - -------------------------------------------------------------------------------- INFO 15:41:05,592 GenomeAnalysisEngine - Strictness is SILENT INFO 15:41:05,691 GenomeAnalysisEngine - Downsampling Settings: Method: BY_SAMPLE, Target Coverage: 1000 INFO 15:41:06,125 MicroScheduler - Running the GATK in parallel mode with 8 total threads, 1 CPU thread(s) for each of 8 data thread(s), of 16 processors available on this machine INFO 15:41:06,167 GenomeAnalysisEngine - Preparing for traversal INFO 15:41:06,181 GenomeAnalysisEngine - Done preparing for traversal INFO 15:41:06,181 ProgressMeter - [INITIALIZATION COMPLETE; STARTING PROCESSING] INFO 15:41:06,181 ProgressMeter - Location processed.sites runtime per.1M.sites completed total.runtime remaining INFO 15:41:06,189 TrainingSet - Found hapmap track: Known = false Training = true Truth = true Prior = Q15.0 INFO 15:41:06,189 TrainingSet - Found omni track: Known = false Training = true Truth = true Prior = Q12.0 INFO 15:41:06,190 TrainingSet - Found 1000G track: Known = false Training = true Truth = false Prior = Q10.0 INFO 15:41:06,190 TrainingSet - Found dbsnp track: Known = true Training = false Truth = false Prior = Q2.0 INFO 15:41:36,860 ProgressMeter - chr3:62558367 1.04e+07 30.0 s 2.0 s 17.7% 2.8 m 2.3 m INFO 15:42:06,861 ProgressMeter - chr7:35476954 2.47e+07 60.0 s 2.0 s 40.5% 2.5 m 88.0 s INFO 15:42:36,861 ProgressMeter - chr11:34029095 3.60e+07 90.0 s 2.0 s 59.0% 2.5 m 62.0 s INFO 15:43:06,862 ProgressMeter - chr16:83086156 4.76e+07 120.0 s 2.0 s 79.5% 2.5 m 31.0 s INFO 15:43:32,353 VariantDataManager - QD: mean = 17.72 standard deviation = 6.45 INFO 15:43:32,496 VariantDataManager - MQ: mean = 59.78 standard deviation = 1.64 INFO 15:43:32,628 VariantDataManager - MQRankSum: mean = 0.13 standard deviation = 0.66 INFO 15:43:32,785 VariantDataManager - ReadPosRankSum: mean = 0.42 standard deviation = 0.63 INFO 15:43:32,933 VariantDataManager - FS: mean = 1.36 standard deviation = 3.03 INFO 15:43:33,064 VariantDataManager - InbreedingCoeff: mean = 0.05 standard deviation = 0.14 INFO 15:43:34,006 VariantDataManager - Annotations are now ordered by their information content: [MQ, QD, MQRankSum, ReadPosRankSum, InbreedingCoeff, FS] INFO 15:43:34,078 VariantDataManager - Training with 1013429 variants after standard deviation thresholding. INFO 15:43:34,082 GaussianMixtureModel - Initializing model with 100 k-means iterations... INFO 15:43:36,863 ProgressMeter - chrY:59358202 5.77e+07 2.5 m 2.0 s 98.7% 2.5 m 2.0 s INFO 15:44:06,864 ProgressMeter - chrY:59358202 5.77e+07 3.0 m 3.0 s 98.7% 3.0 m 2.0 s INFO 15:44:36,865 ProgressMeter - chrY:59358202 5.77e+07 3.5 m 3.0 s 98.7% 3.5 m 2.0 s INFO 15:44:52,281 VariantRecalibratorEngine - Finished iteration 0. INFO 15:45:06,866 ProgressMeter - chrY:59358202 5.77e+07 4.0 m 4.0 s 98.7% 4.1 m 3.0 s INFO 15:45:22,350 VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 1.22733 INFO 15:45:36,867 ProgressMeter - chrY:59358202 5.77e+07 4.5 m 4.0 s 98.7% 4.6 m 3.0 s INFO 15:45:52,658 VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.38969 INFO 15:46:06,868 ProgressMeter - chrY:59358202 5.77e+07 5.0 m 5.0 s 98.7% 5.1 m 4.0 s INFO 15:46:23,633 VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.23704 INFO 15:46:36,869 ProgressMeter - chrY:59358202 5.77e+07 5.5 m 5.0 s 98.7% 5.6 m 4.0 s INFO 15:46:54,745 VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.10031 INFO 15:47:06,870 ProgressMeter - chrY:59358202 5.77e+07 6.0 m 6.0 s 98.7% 6.1 m 4.0 s INFO 15:47:26,278 VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.05054 INFO 15:47:36,871 ProgressMeter - chrY:59358202 5.77e+07 6.5 m 6.0 s 98.7% 6.6 m 5.0 s INFO 15:47:57,567 VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.05771 INFO 15:48:06,872 ProgressMeter - chrY:59358202 5.77e+07 7.0 m 7.0 s 98.7% 7.1 m 5.0 s INFO 15:48:28,752 VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.06142 INFO 15:48:46,873 ProgressMeter - chrY:59358202 5.77e+07 7.7 m 7.0 s 98.7% 7.8 m 6.0 s INFO 15:48:59,850 VariantRecalibratorEngine - Finished iteration 40. Current change in mixture coefficients = 0.04468 INFO 15:49:26,874 ProgressMeter - chrY:59358202 5.77e+07 8.3 m 8.0 s 98.7% 8.4 m 6.0 s INFO 15:49:31,308 VariantRecalibratorEngine - Finished iteration 45. Current change in mixture coefficients = 0.02853 INFO 15:50:02,444 VariantRecalibratorEngine - Finished iteration 50. Current change in mixture coefficients = 0.01561 INFO 15:50:06,875 ProgressMeter - chrY:59358202 5.77e+07 9.0 m 9.0 s 98.7% 9.1 m 7.0 s INFO 15:50:33,543 VariantRecalibratorEngine - Finished iteration 55. Current change in mixture coefficients = 0.00767 INFO 15:50:46,876 ProgressMeter - chrY:59358202 5.77e+07 9.7 m 10.0 s 98.7% 9.8 m 7.0 s INFO 15:51:05,063 VariantRecalibratorEngine - Finished iteration 60. Current change in mixture coefficients = 0.00360 INFO 15:51:26,877 ProgressMeter - chrY:59358202 5.77e+07 10.3 m 10.0 s 98.7% 10.5 m 8.0 s INFO 15:51:30,026 VariantRecalibratorEngine - Convergence after 64 iterations! INFO 15:51:34,452 VariantRecalibratorEngine - Evaluating full set of 1836763 variants... INFO 15:51:56,878 ProgressMeter - chrY:59358202 5.77e+07 10.8 m 11.0 s 98.7% 11.0 m 8.0 s INFO 15:51:58,236 VariantDataManager - Training with worst 96353 scoring variants --> variants with LOD <= -5.0000. INFO 15:51:58,236 GaussianMixtureModel - Initializing model with 100 k-means iterations... INFO 15:52:02,403 VariantRecalibratorEngine - Finished iteration 0. INFO 15:52:03,301 VariantRecalibratorEngine - Finished iteration 5. Current change in mixture coefficients = 0.00842 INFO 15:52:04,201 VariantRecalibratorEngine - Finished iteration 10. Current change in mixture coefficients = 0.05649 INFO 15:52:05,099 VariantRecalibratorEngine - Finished iteration 15. Current change in mixture coefficients = 0.00645 INFO 15:52:05,997 VariantRecalibratorEngine - Finished iteration 20. Current change in mixture coefficients = 0.02104 INFO 15:52:06,903 VariantRecalibratorEngine - Finished iteration 25. Current change in mixture coefficients = 0.01804 INFO 15:52:07,809 VariantRecalibratorEngine - Finished iteration 30. Current change in mixture coefficients = 0.00751 INFO 15:52:08,720 VariantRecalibratorEngine - Finished iteration 35. Current change in mixture coefficients = 0.00220 INFO 15:52:08,901 VariantRecalibratorEngine - Convergence after 36 iterations! INFO 15:52:09,072 VariantRecalibratorEngine - Evaluating full set of 1836763 variants... INFO 15:52:35,375 TrancheManager - Finding 8 tranches for 1836763 variants INFO 15:52:36,473 TrancheManager - Tranche threshold 100.00 => selection metric threshold 0.000 INFO 15:52:36,661 TrancheManager - Found tranche for 100.000: 0.000 threshold starting with variant 0; running score is 0.000 INFO 15:52:36,661 TrancheManager - Tranche is Tranche ts=100.00 minVQSLod=-6230.3360 known=(1309038 @ 2.3725) novel=(527725 @ 1.9130) truthSites(400524 accessible, 400524 called), name=anonymous] INFO 15:52:36,661 TrancheManager - Tranche threshold 99.90 => selection metric threshold 0.001 INFO 15:52:36,860 TrancheManager - Found tranche for 99.900: 0.001 threshold starting with variant 86230; running score is 0.001 INFO 15:52:36,860 TrancheManager - Tranche is Tranche ts=99.90 minVQSLod=-4.2226 known=(1280865 @ 2.3857) novel=(469668 @ 1.9562) truthSites(400524 accessible, 400123 called), name=anonymous] INFO 15:52:36,861 TrancheManager - Tranche threshold 99.00 => selection metric threshold 0.010 INFO 15:52:36,879 ProgressMeter - chrY:59358202 5.77e+07 11.5 m 11.0 s 98.7% 11.7 m 9.0 s INFO 15:52:37,035 TrancheManager - Found tranche for 99.000: 0.010 threshold starting with variant 244874; running score is 0.010 INFO 15:52:37,036 TrancheManager - Tranche is Tranche ts=99.00 minVQSLod=0.6282 known=(1200165 @ 2.4101) novel=(391724 @ 1.9915) truthSites(400524 accessible, 396518 called), name=anonymous] INFO 15:52:37,036 TrancheManager - Tranche threshold 97.50 => selection metric threshold 0.025 INFO 15:52:37,211 TrancheManager - Found tranche for 97.500: 0.025 threshold starting with variant 316232; running score is 0.025 INFO 15:52:37,211 TrancheManager - Tranche is Tranche ts=97.50 minVQSLod=3.8960 known=(1147756 @ 2.4138) novel=(372775 @ 2.0174) truthSites(400524 accessible, 390510 called), name=anonymous] INFO 15:52:37,211 TrancheManager - Tranche threshold 95.00 => selection metric threshold 0.050 INFO 15:52:37,385 TrancheManager - Found tranche for 95.000: 0.050 threshold starting with variant 382474; running score is 0.050 INFO 15:52:37,385 TrancheManager - Tranche is Tranche ts=95.00 minVQSLod=13.9019 known=(1109420 @ 2.4177) novel=(344869 @ 2.0259) truthSites(400524 accessible, 380497 called), name=anonymous] INFO 15:52:37,386 TrancheManager - Tranche threshold 92.50 => selection metric threshold 0.075 INFO 15:52:37,553 TrancheManager - Found tranche for 92.500: 0.075 threshold starting with variant 675609; running score is 0.075 INFO 15:52:37,553 TrancheManager - Tranche is Tranche ts=92.50 minVQSLod=15.9418 known=(983868 @ 2.4010) novel=(177286 @ 1.8445) truthSites(400524 accessible, 370484 called), name=anonymous] INFO 15:52:37,554 TrancheManager - Tranche threshold 90.00 => selection metric threshold 0.100 INFO 15:52:37,719 TrancheManager - Found tranche for 90.000: 0.100 threshold starting with variant 812697; running score is 0.100 INFO 15:52:37,719 TrancheManager - Tranche is Tranche ts=90.00 minVQSLod=16.6133 known=(898280 @ 2.3935) novel=(125786 @ 1.7399) truthSites(400524 accessible, 360471 called), name=anonymous] INFO 15:52:37,719 TrancheManager - Tranche threshold 85.00 => selection metric threshold 0.150 INFO 15:52:37,882 TrancheManager - Found tranche for 85.000: 0.150 threshold starting with variant 988478; running score is 0.150 INFO 15:52:37,882 TrancheManager - Tranche is Tranche ts=85.00 minVQSLod=17.1595 known=(763314 @ 2.3786) novel=(84971 @ 1.6080) truthSites(400524 accessible, 340445 called), name=anonymous] INFO 15:52:37,885 VariantRecalibrator - Writing out recalibration table... INFO 15:52:51,654 VariantRecalibrator - Writing out visualization Rscript file... INFO 15:52:51,784 VariantRecalibrator - Building MQ x QD plot... INFO 15:52:51,789 VariantRecalibratorEngine - Evaluating full set of 3600 variants... INFO 15:52:52,749 VariantRecalibratorEngine - Evaluating full set of 3600 variants... INFO 15:52:53,126 VariantRecalibrator - Building MQ x MQRankSum plot... INFO 15:52:53,128 VariantRecalibratorEngine - Evaluating full set of 3600 variants... INFO 15:52:54,088 VariantRecalibratorEngine - Evaluating full set of 3600 variants... INFO 15:52:54,417 VariantRecalibrator - Building MQ x ReadPosRankSum plot... INFO 15:52:54,418 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:52:55,395 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:52:55,710 VariantRecalibrator - Building MQ x InbreedingCoeff plot... INFO 15:52:55,711 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:52:56,719 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:52:57,053 VariantRecalibrator - Building MQ x FS plot... INFO 15:52:57,054 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:52:58,030 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:52:58,350 VariantRecalibrator - Building QD x MQRankSum plot... INFO 15:52:58,351 VariantRecalibratorEngine - Evaluating full set of 3600 variants... INFO 15:52:59,311 VariantRecalibratorEngine - Evaluating full set of 3600 variants... INFO 15:52:59,624 VariantRecalibrator - Building QD x ReadPosRankSum plot... INFO 15:52:59,625 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:00,600 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:00,917 VariantRecalibrator - Building QD x InbreedingCoeff plot... INFO 15:53:00,918 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:01,925 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:02,257 VariantRecalibrator - Building QD x FS plot... INFO 15:53:02,257 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:03,233 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:03,552 VariantRecalibrator - Building MQRankSum x ReadPosRankSum plot... INFO 15:53:03,552 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:04,528 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:04,844 VariantRecalibrator - Building MQRankSum x InbreedingCoeff plot... INFO 15:53:04,845 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:05,851 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:06,183 VariantRecalibrator - Building MQRankSum x FS plot... INFO 15:53:06,183 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:07,159 VariantRecalibratorEngine - Evaluating full set of 3660 variants... INFO 15:53:07,478 VariantRecalibrator - Building ReadPosRankSum x InbreedingCoeff plot... INFO 15:53:07,478 VariantRecalibratorEngine - Evaluating full set of 3721 variants... INFO 15:53:08,503 VariantRecalibratorEngine - Evaluating full set of 3721 variants... INFO 15:53:08,838 VariantRecalibrator - Building ReadPosRankSum x FS plot... INFO 15:53:08,839 VariantRecalibratorEngine - Evaluating full set of 3721 variants... INFO 15:53:09,832 VariantRecalibratorEngine - Evaluating full set of 3721 variants... INFO 15:53:10,154 VariantRecalibrator - Building InbreedingCoeff x FS plot... INFO 15:53:10,155 VariantRecalibratorEngine - Evaluating full set of 3721 variants... INFO 15:53:11,180 VariantRecalibratorEngine - Evaluating full set of 3721 variants... INFO 15:53:11,519 VariantRecalibrator - Executing: Rscript recalibrate_SNP_plots2_1000bp_4.R WARN 15:53:13,459 RScriptExecutor - RScript exited with 1. Run with -l DEBUG for more info. INFO 15:53:13,460 VariantRecalibrator - Executing: Rscript (resource)org/broadinstitute/sting/gatk/walkers/variantrecalibration/plot_Tranches.R Measles_1000bp_4.tranches 2.15 INFO 15:53:16,880 ProgressMeter - chrY:59358202 5.77e+07 12.2 m 12.0 s 98.7% 12.3 m 9.0 s INFO 15:53:46,880 ProgressMeter - chrY:59358202 5.77e+07 12.7 m 13.0 s 98.7% 12.8 m 10.0 s INFO 15:54:16,881 ProgressMeter - chrY:59358202 5.77e+07 13.2 m 13.0 s 98.7% 13.3 m 10.0 s INFO 15:54:56,881 ProgressMeter - chrY:59358202 5.77e+07 13.8 m 14.0 s 98.7% 14.0 m 11.0 s INFO 15:55:26,882 ProgressMeter - chrY:59358202 5.77e+07 14.3 m 14.0 s 98.7% 14.5 m 11.0 s INFO 15:55:45,445 ProgressMeter - done 5.77e+07 14.7 m 15.0 s 98.7% 14.8 m 11.0 s INFO 15:55:45,445 ProgressMeter - Total runtime 879.26 secs, 14.65 min, 0.24 hours INFO 15:55:48,517 GATKRunReport - Uploaded run statistics report to AWS S3 real 14m46.485s user 20m23.623s sys 3m48.709s