Duration and Heterozygosity

[rmormando]

Hi I'm trying to run nPhase on a tetraploid yeast genome I seqeunced with PacBio HiFi reads.

Here is my code:

nphase pipeline --sampleName trialRun1 --reference s288c.fa --longReads pacbioHiFireads.fastq.gz --longReadPlatform pacbio --R1 illuminaShortRead_1.fastq --R2 illuminaShortRead_2.fastq --output trialRun1Output --threads 8

The issue I am having is that it's taking a long time to run - my computer accidentally restarted during its run so the progress I made running it for the past day or two is gone and before I run the code again I wanted to see if there was a tag or something I could add or do to the data to make it go faster.

I saw your messages in issue #11 and #10 but was wondering if there was anything done to the nPhase code to account for this. I also read up on your solution to #12 but I'm not sure how to go about doing that. I can run the code using the command I have written out above and I don't mind if it takes a longer amount of time but how much time on average would it take for a tetraploid yeast genome to run through nPhase?

[OmarOakheart]

Before starting over from scratch, you should check if the long read mapping, short read mapping and variant calling steps were over. If so, then you can save a lot of time by running nphase partial instead of rerunning the entire pipeline (since you only need to map and variant call once). Realistically if it ran for an entire day I would expect at least one of the mapping steps to be over, unless if you have a particularly high coverage/slow processing.

If you have any output in the Phased folder, that's a good sign that all of the previous steps are over. If you're unsure how to determine if the pre-processing steps ended I can look into it later and give you some pretty clear ways of identifying if something was interrupted partway through

[rmormando]

It looks like there is data in both the long read and short read mapping folders but there are two empty folders (FastQ and Plots) in the Phased folder, which I'm guessing means that it cut off right in the middle of the phasing step?

what would the command look like to just do the partial run? If you can look into that later and let me know some ways to see its progress that would be really helpful!

[OmarOakheart]

If the long reads are mapped and the short reads are mapped and variant called, then you can run

nphase partial --sampleName SAMPLE_NAME --reference REFERENCE --output OUTPUT_FOLDER --longReads LONG_READ_FILE --vcf VCF_FILE --mappedLongReads MAPPED_LONG_READ_FILE --threads 8

Where MAPPED_LONG_READ_FILE looks like ${OUTPUT_FOLDER}/longReads/${SAMPLE_NAME}.sorted.sam
and VCF_FILE looks like ${OUTPUT_FOLDER}/variantCalled/shortReads/${SAMPLE_NAME}.SNPs.vcf

If the variant calling wasn't over but the short reads were mapped, then it's

nphase partial --sampleName SAMPLE_NAME --reference REFERENCE --output OUTPUT_FOLDER --longReads LONG_READ_FILE --mappedLongReads MAPPED_LONG_READ_FILE --mappedShortReads MAPPED_SHORT_READ_FILE --threads 8

where MAPPED_SHORT_READ_FILE looks like ${OUTPUT_FOLDER}/shortReads/${SAMPLE_NAME}.final.bam

[rmormando]

Hello! I'm so sorry for the long wait - I started working through other projects but I have finally circled back to this issue and I have some updates.

I went to run nphase partial using the mapped long read SAM and VCF files from the resulting run when I used nphase pipeline. After running for about ~2 hours it printed this error to the STDOUT:

Long reads successfully mapped to reference
Removing quality 0 (multimapped) reads, turning to bam and sorting it
Short reads successfully mapped to reference
Identified heterozygous SNPs in short read VCF
Extracted heterozygous SNP info based on short read VCF
Identified heterozygous SNPs in short read VCF
Extracted heterozygous SNP info based on short read VCF

And then this is what was in the log file:

COMMAND: gatk CreateSequenceDictionary -R Saccharomyces_cerevisiae.fasta

STDERR:

INFO	2022-12-13 17:07:36	CreateSequenceDictionary	Output dictionary will be written in Saccharomyces_cerevisiae.dict
17:07:36.994 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
[Tue Dec 13 17:07:37 UTC 2022] CreateSequenceDictionary --REFERENCE Saccharomyces_cerevisiae.fasta --TRUNCATE_NAMES_AT_WHITESPACE true --NUM_SEQUENCES 2147483647 --VERBOSITY INFO --QUIET false --VALIDATION_STRINGENCY STRICT --COMPRESSION_LEVEL 2 --MAX_RECORDS_IN_RAM 500000 --CREATE_INDEX false --CREATE_MD5_FILE false --GA4GH_CLIENT_SECRETS client_secrets.json --help false --version false --showHidden false --USE_JDK_DEFLATER false --USE_JDK_INFLATER false
[Tue Dec 13 17:07:37 UTC 2022] Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux 5.10.155-138.670.amzn2.x86_64 amd64; OpenJDK 64-Bit Server VM 11.0.1+13-LTS; Deflater: Intel; Inflater: Intel; Provider GCS is available; Picard version: Version:4.3.0.0
[Tue Dec 13 17:07:37 UTC 2022] picard.sam.CreateSequenceDictionary done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=159383552
To get help, see http://broadinstitute.github.io/picard/index.html#GettingHelp
picard.PicardException: /home/ec2-user/Saccharomyces_cerevisiae.dict already exists.  Delete this file and try again, or specify a different output file.
	at picard.sam.CreateSequenceDictionary.doWork(CreateSequenceDictionary.java:220)
	at picard.cmdline.CommandLineProgram.instanceMain(CommandLineProgram.java:309)
	at org.broadinstitute.hellbender.cmdline.PicardCommandLineProgramExecutor.instanceMain(PicardCommandLineProgramExecutor.java:37)
	at org.broadinstitute.hellbender.Main.runCommandLineProgram(Main.java:160)
	at org.broadinstitute.hellbender.Main.mainEntry(Main.java:203)
	at org.broadinstitute.hellbender.Main.main(Main.java:289)
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar CreateSequenceDictionary -R Saccharomyces_cerevisiae.fasta


STDOUT:



COMMAND: gatk SelectVariants -R Saccharomyces_cerevisiae.fasta --variant ./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf -O ./nphase_work/OYL011/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf --select-type-to-include SNP

STDERR:

17:07:40.064 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
17:07:40.200 INFO  SelectVariants - ------------------------------------------------------------
17:07:40.201 INFO  SelectVariants - The Genome Analysis Toolkit (GATK) v4.3.0.0
17:07:40.201 INFO  SelectVariants - For support and documentation go to https://software.broadinstitute.org/gatk/
17:07:40.201 INFO  SelectVariants - Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux v5.10.155-138.670.amzn2.x86_64 amd64
17:07:40.201 INFO  SelectVariants - Java runtime: OpenJDK 64-Bit Server VM v11.0.1+13-LTS
17:07:40.201 INFO  SelectVariants - Start Date/Time: December 13, 2022 at 5:07:39 PM UTC
17:07:40.202 INFO  SelectVariants - ------------------------------------------------------------
17:07:40.202 INFO  SelectVariants - ------------------------------------------------------------
17:07:40.202 INFO  SelectVariants - HTSJDK Version: 3.0.1
17:07:40.202 INFO  SelectVariants - Picard Version: 2.27.5
17:07:40.202 INFO  SelectVariants - Built for Spark Version: 2.4.5
17:07:40.203 INFO  SelectVariants - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:07:40.203 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:07:40.203 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:07:40.203 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:07:40.203 INFO  SelectVariants - Deflater: IntelDeflater
17:07:40.203 INFO  SelectVariants - Inflater: IntelInflater
17:07:40.203 INFO  SelectVariants - GCS max retries/reopens: 20
17:07:40.203 INFO  SelectVariants - Requester pays: disabled
17:07:40.203 INFO  SelectVariants - Initializing engine
17:07:40.395 INFO  FeatureManager - Using codec VCFCodec to read file file:///home/ec2-user/./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf
17:07:40.435 INFO  SelectVariants - Done initializing engine
17:07:40.488 INFO  ProgressMeter - Starting traversal
17:07:40.488 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
17:07:42.946 INFO  ProgressMeter -        chrXVI:941337              0.0                 86639        2114865.7
17:07:42.947 INFO  ProgressMeter - Traversal complete. Processed 86639 total variants in 0.0 minutes.
17:07:42.953 INFO  SelectVariants - Shutting down engine
[December 13, 2022 at 5:07:42 PM UTC] org.broadinstitute.hellbender.tools.walkers.variantutils.SelectVariants done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=235929600
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar SelectVariants -R Saccharomyces_cerevisiae.fasta --variant ./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf -O ./nphase_work/OYL011/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf --select-type-to-include SNP


STDOUT:



COMMAND: gatk CreateSequenceDictionary -R Saccharomyces_cerevisiae.fasta

STDERR:

INFO	2022-12-13 17:08:30	CreateSequenceDictionary	Output dictionary will be written in Saccharomyces_cerevisiae.dict
17:08:30.548 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
[Tue Dec 13 17:08:30 UTC 2022] CreateSequenceDictionary --REFERENCE Saccharomyces_cerevisiae.fasta --TRUNCATE_NAMES_AT_WHITESPACE true --NUM_SEQUENCES 2147483647 --VERBOSITY INFO --QUIET false --VALIDATION_STRINGENCY STRICT --COMPRESSION_LEVEL 2 --MAX_RECORDS_IN_RAM 500000 --CREATE_INDEX false --CREATE_MD5_FILE false --GA4GH_CLIENT_SECRETS client_secrets.json --help false --version false --showHidden false --USE_JDK_DEFLATER false --USE_JDK_INFLATER false
[Tue Dec 13 17:08:30 UTC 2022] Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux 5.10.155-138.670.amzn2.x86_64 amd64; OpenJDK 64-Bit Server VM 11.0.1+13-LTS; Deflater: Intel; Inflater: Intel; Provider GCS is available; Picard version: Version:4.3.0.0
[Tue Dec 13 17:08:30 UTC 2022] picard.sam.CreateSequenceDictionary done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=191889408
To get help, see http://broadinstitute.github.io/picard/index.html#GettingHelp
picard.PicardException: /home/ec2-user/Saccharomyces_cerevisiae.dict already exists.  Delete this file and try again, or specify a different output file.
	at picard.sam.CreateSequenceDictionary.doWork(CreateSequenceDictionary.java:220)
	at picard.cmdline.CommandLineProgram.instanceMain(CommandLineProgram.java:309)
	at org.broadinstitute.hellbender.cmdline.PicardCommandLineProgramExecutor.instanceMain(PicardCommandLineProgramExecutor.java:37)
	at org.broadinstitute.hellbender.Main.runCommandLineProgram(Main.java:160)
	at org.broadinstitute.hellbender.Main.mainEntry(Main.java:203)
	at org.broadinstitute.hellbender.Main.main(Main.java:289)
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar CreateSequenceDictionary -R Saccharomyces_cerevisiae.fasta


STDOUT:



COMMAND: gatk SelectVariants -R Saccharomyces_cerevisiae.fasta --variant ./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf -O ./nphase_work/OYL011/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf --select-type-to-include SNP

STDERR:

17:08:33.451 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
17:08:33.594 INFO  SelectVariants - ------------------------------------------------------------
17:08:33.595 INFO  SelectVariants - The Genome Analysis Toolkit (GATK) v4.3.0.0
17:08:33.595 INFO  SelectVariants - For support and documentation go to https://software.broadinstitute.org/gatk/
17:08:33.595 INFO  SelectVariants - Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux v5.10.155-138.670.amzn2.x86_64 amd64
17:08:33.595 INFO  SelectVariants - Java runtime: OpenJDK 64-Bit Server VM v11.0.1+13-LTS
17:08:33.595 INFO  SelectVariants - Start Date/Time: December 13, 2022 at 5:08:33 PM UTC
17:08:33.595 INFO  SelectVariants - ------------------------------------------------------------
17:08:33.596 INFO  SelectVariants - ------------------------------------------------------------
17:08:33.596 INFO  SelectVariants - HTSJDK Version: 3.0.1
17:08:33.596 INFO  SelectVariants - Picard Version: 2.27.5
17:08:33.596 INFO  SelectVariants - Built for Spark Version: 2.4.5
17:08:33.597 INFO  SelectVariants - HTSJDK Defaults.COMPRESSION_LEVEL : 2
17:08:33.597 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
17:08:33.597 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
17:08:33.597 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
17:08:33.597 INFO  SelectVariants - Deflater: IntelDeflater
17:08:33.597 INFO  SelectVariants - Inflater: IntelInflater
17:08:33.597 INFO  SelectVariants - GCS max retries/reopens: 20
17:08:33.597 INFO  SelectVariants - Requester pays: disabled
17:08:33.597 INFO  SelectVariants - Initializing engine
17:08:33.788 INFO  FeatureManager - Using codec VCFCodec to read file file:///home/ec2-user/./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf
17:08:33.815 INFO  SelectVariants - Done initializing engine
17:08:33.868 INFO  ProgressMeter - Starting traversal
17:08:33.873 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
17:08:36.278 INFO  ProgressMeter -        chrXVI:941337              0.0                 86639        2162371.0
17:08:36.278 INFO  ProgressMeter - Traversal complete. Processed 86639 total variants in 0.0 minutes.
17:08:36.328 INFO  SelectVariants - Shutting down engine
[December 13, 2022 at 5:08:36 PM UTC] org.broadinstitute.hellbender.tools.walkers.variantutils.SelectVariants done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=273678336
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar SelectVariants -R Saccharomyces_cerevisiae.fasta --variant ./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf -O ./nphase_work/OYL011/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf --select-type-to-include SNP


STDOUT:



COMMAND: gatk CreateSequenceDictionary -R Saccharomyces_cerevisiae.fasta

STDERR:

INFO	2022-12-13 19:22:37	CreateSequenceDictionary	Output dictionary will be written in Saccharomyces_cerevisiae.dict
19:22:37.520 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
[Tue Dec 13 19:22:37 UTC 2022] CreateSequenceDictionary --REFERENCE Saccharomyces_cerevisiae.fasta --TRUNCATE_NAMES_AT_WHITESPACE true --NUM_SEQUENCES 2147483647 --VERBOSITY INFO --QUIET false --VALIDATION_STRINGENCY STRICT --COMPRESSION_LEVEL 2 --MAX_RECORDS_IN_RAM 500000 --CREATE_INDEX false --CREATE_MD5_FILE false --GA4GH_CLIENT_SECRETS client_secrets.json --help false --version false --showHidden false --USE_JDK_DEFLATER false --USE_JDK_INFLATER false
[Tue Dec 13 19:22:37 UTC 2022] Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux 5.10.155-138.670.amzn2.x86_64 amd64; OpenJDK 64-Bit Server VM 11.0.1+13-LTS; Deflater: Intel; Inflater: Intel; Provider GCS is available; Picard version: Version:4.3.0.0
[Tue Dec 13 19:22:37 UTC 2022] picard.sam.CreateSequenceDictionary done. Elapsed time: 0.01 minutes.
Runtime.totalMemory()=159383552
To get help, see http://broadinstitute.github.io/picard/index.html#GettingHelp
picard.PicardException: /home/ec2-user/Saccharomyces_cerevisiae.dict already exists.  Delete this file and try again, or specify a different output file.
	at picard.sam.CreateSequenceDictionary.doWork(CreateSequenceDictionary.java:220)
	at picard.cmdline.CommandLineProgram.instanceMain(CommandLineProgram.java:309)
	at org.broadinstitute.hellbender.cmdline.PicardCommandLineProgramExecutor.instanceMain(PicardCommandLineProgramExecutor.java:37)
	at org.broadinstitute.hellbender.Main.runCommandLineProgram(Main.java:160)
	at org.broadinstitute.hellbender.Main.mainEntry(Main.java:203)
	at org.broadinstitute.hellbender.Main.main(Main.java:289)
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar CreateSequenceDictionary -R Saccharomyces_cerevisiae.fasta


STDOUT:



COMMAND: gatk SelectVariants -R Saccharomyces_cerevisiae.fasta --variant ./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf -O ./nphase_work/OYL011/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf --select-type-to-include SNP

STDERR:

19:22:40.475 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
19:22:40.628 INFO  SelectVariants - ------------------------------------------------------------
19:22:40.629 INFO  SelectVariants - The Genome Analysis Toolkit (GATK) v4.3.0.0
19:22:40.629 INFO  SelectVariants - For support and documentation go to https://software.broadinstitute.org/gatk/
19:22:40.629 INFO  SelectVariants - Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux v5.10.155-138.670.amzn2.x86_64 amd64
19:22:40.629 INFO  SelectVariants - Java runtime: OpenJDK 64-Bit Server VM v11.0.1+13-LTS
19:22:40.629 INFO  SelectVariants - Start Date/Time: December 13, 2022 at 7:22:40 PM UTC
19:22:40.629 INFO  SelectVariants - ------------------------------------------------------------
19:22:40.629 INFO  SelectVariants - ------------------------------------------------------------
19:22:40.630 INFO  SelectVariants - HTSJDK Version: 3.0.1
19:22:40.630 INFO  SelectVariants - Picard Version: 2.27.5
19:22:40.630 INFO  SelectVariants - Built for Spark Version: 2.4.5
19:22:40.630 INFO  SelectVariants - HTSJDK Defaults.COMPRESSION_LEVEL : 2
19:22:40.630 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
19:22:40.630 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
19:22:40.631 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
19:22:40.631 INFO  SelectVariants - Deflater: IntelDeflater
19:22:40.631 INFO  SelectVariants - Inflater: IntelInflater
19:22:40.631 INFO  SelectVariants - GCS max retries/reopens: 20
19:22:40.631 INFO  SelectVariants - Requester pays: disabled
19:22:40.631 INFO  SelectVariants - Initializing engine
19:22:40.823 INFO  FeatureManager - Using codec VCFCodec to read file file:///home/ec2-user/./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf
19:22:40.861 INFO  SelectVariants - Done initializing engine
19:22:40.910 INFO  ProgressMeter - Starting traversal
19:22:40.917 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
19:22:43.227 INFO  ProgressMeter -        chrXVI:941337              0.0                 86639        2251338.2
19:22:43.227 INFO  ProgressMeter - Traversal complete. Processed 86639 total variants in 0.0 minutes.
19:22:43.284 INFO  SelectVariants - Shutting down engine
[December 13, 2022 at 7:22:43 PM UTC] org.broadinstitute.hellbender.tools.walkers.variantutils.SelectVariants done. Elapsed time: 0.05 minutes.
Runtime.totalMemory()=255852544
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar SelectVariants -R Saccharomyces_cerevisiae.fasta --variant ./nphase_work/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf -O ./nphase_work/OYL011/OYL011/VariantCalls/shortReads/OYL011.SNPs.vcf --select-type-to-include SNP


STDOUT:

Oof! I know this turned in to a long message but is there anything I can do to fix this? It's doing everything BUT phasing my sample and I don't know what I'm doing wrong. Thank you in advance!!

Other info:
version: 1.2.0
OS: AWS EC2 Linux Instance

[OmarOakheart]

Based on your output it looks like, for some reason, the GATK variant selection is happening twice simultaneously. Is there any possible way you somehow ran the same command line twice? I'll be checking the code to see if there's a bug no one's ran into before.

What I think is most efficient and definitely what I would do, is download the example data in https://github.com/OmarOakheart/nPhase/tree/master/example, then run it and check that it works properly (it should be over in a matter of minutes). If it does work fine, then my recommendation is to just start over with your raw. There's still a risk that by accidentally restarting in the middle of a run you had an incomplete BAM file or something of that nature and now we're seeing weird things happen because the input is weird, better to rule that out quickly in my opinion.

If you're strapped for computing time let me know and I can try to come up with another recommendation

[rmormando]

I ran through the pipeline with the example data and it went all the way through and finished fine so I am going to go back and rerun it. I'll let you know what happens!

[rmormando]

Hello again! I reran the pipeline and it ended at virtually the same spot:

This was printed in the STDOUT:

Long reads successfully mapped to reference
Removing quality 0 (multimapped) reads, turning to bam and sorting it
Short reads successfully mapped to reference
Identified heterozygous SNPs in short read VCF
Extracted heterozygous SNP info based on short read VCF
Identified heterozygous SNPs in short read VCF
Extracted heterozygous SNP info based on short read VCF
Long reads successfully mapped to reference
Removing quality 0 (multimapped) reads, turning to bam and sorting it
Short reads successfully mapped to reference
Identified heterozygous SNPs in short read VCF
Extracted heterozygous SNP info based on short read VCF

And this is the log file:

COMMAND: gatk CreateSequenceDictionary -R Saccharomyces_cerevisiae.fasta

STDERR:

INFO	2022-12-14 17:01:49	CreateSequenceDictionary	Output dictionary will be written in Saccharomyces_cerevisiae.dict
17:01:49.650 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
[Wed Dec 14 17:01:49 UTC 2022] CreateSequenceDictionary --REFERENCE Saccharomyces_cerevisiae.fasta --TRUNCATE_NAMES_AT_WHITESPACE true --NUM_SEQUENCES 2147483647 --VERBOSITY INFO --QUIET false --VALIDATION_STRINGENCY STRICT --COMPRESSION_LEVEL 2 --MAX_RECORDS_IN_RAM 500000 --CREATE_INDEX false --CREATE_MD5_FILE false --GA4GH_CLIENT_SECRETS client_secrets.json --help false --version false --showHidden false --USE_JDK_DEFLATER false --USE_JDK_INFLATER false
[Wed Dec 14 17:01:49 UTC 2022] Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux 5.10.155-138.670.amzn2.x86_64 amd64; OpenJDK 64-Bit Server VM 11.0.1+13-LTS; Deflater: Intel; Inflater: Intel; Provider GCS is available; Picard version: Version:4.3.0.0
[Wed Dec 14 17:01:49 UTC 2022] picard.sam.CreateSequenceDictionary done. Elapsed time: 0.00 minutes.
Runtime.totalMemory()=159383552
To get help, see http://broadinstitute.github.io/picard/index.html#GettingHelp
picard.PicardException: /home/ec2-user/Saccharomyces_cerevisiae.dict already exists.  Delete this file and try again, or specify a different output file.
	at picard.sam.CreateSequenceDictionary.doWork(CreateSequenceDictionary.java:220)
	at picard.cmdline.CommandLineProgram.instanceMain(CommandLineProgram.java:309)
	at org.broadinstitute.hellbender.cmdline.PicardCommandLineProgramExecutor.instanceMain(PicardCommandLineProgramExecutor.java:37)
	at org.broadinstitute.hellbender.Main.runCommandLineProgram(Main.java:160)
	at org.broadinstitute.hellbender.Main.mainEntry(Main.java:203)
	at org.broadinstitute.hellbender.Main.main(Main.java:289)
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar CreateSequenceDictionary -R Saccharomyces_cerevisiae.fasta


STDOUT:



COMMAND: ngmlr -t 8 -x ont -r Saccharomyces_cerevisiae.fasta -q OYL-011_passMinQ7.fastq -o ./nphase_work/ag_OYL011/Mapped/longReads/ag_OYL011.sam

STDERR:

ngmlr 0.2.7 (build: Feb 21 2022 18:53:53, start: 2022-12-14.17:01:49)
Contact: philipp.rescheneder@univie.ac.at
Opening for output (SAM): ./nphase_work/ag_OYL011/Mapped/longReads/ag_OYL011.sam
Reading encoded reference from Saccharomyces_cerevisiae.fasta-enc.2.ngm
Reading 12 Mbp from disk took 0.04s
Reading reference index from Saccharomyces_cerevisiae.fasta-ht-13-2.2.ngm
Reading from disk took 2.58s
Opening query file OYL-011_passMinQ7.fastq
Mapping reads...
Processed: 29 (0.97), R/S: 14.50, RL: 23375, Time: 3.00 1.50 44.00, Align: 1.00, 485, 0.93
�[A�[2KProcessed: 95 (0.96), R/S: 23.75, RL: 11878, Time: 5.31 2.42 87.53, Align: 1.00, 425, 0.94
�[A�[2KProcessed: 119 (0.96), R/S: 19.83, RL: 10906, Time: 5.33 2.11 90.13, Align: 0.99, 539, 0.93
�[A�[2KProcessed: 162 (0.96), R/S: 20.25, RL: 10456, Time: 4.51 1.75 91.50, Align: 1.00, 529, 0.93
�[A�[2KProcessed: 186 (0.96), R/S: 18.60, RL: 10979, Time: 2.69 1.34 93.94, Align: 1.00, 575, 0.94
�...
�[A�[2KProcessed: 127373 (0.95), R/S: 12.59, RL: 7900, Time: 3.07 1.00 92.93, Align: 0.99, 534, 0.93
�[A�[2KProcessed: 127400 (0.95), R/S: 12.59, RL: 7898, Time: 3.19 1.00 92.81, Align: 0.99, 534, 0.93
�[A�[2KProcessed: 127402 (0.95), R/S: 12.59, RL: 7898, Time: 3.09 1.00 92.91, Align: 0.99, 534, 0.93
�[A�[2KProcessed: 127402 (0.95), R/S: 12.59, RL: 7898, Time: 3.09 1.00 92.91, Align: 0.99, 534, 0.93
Done (120626 reads mapped (94.68%), 6776 reads not mapped, 153868 lines written)(elapsed: 168m, 11 r/s)


STDOUT:


COMMAND: samtools view -t Saccharomyces_cerevisiae.fasta -@ 8 -F 260 ./nphase_work/ag_OYL011/Mapped/longReads/ag_OYL011.sam -o ./nphase_work/ag_OYL011/Mapped/longReads/ag_OYL011.pass.sam

COMMAND: samtools sort ./nphase_work/ag_OYL011/Mapped/longReads/ag_OYL011.pass.sam -@ 8 -o ./nphase_work/ag_OYL011/Mapped/longReads/ag_OYL011.sorted.header.sam

STDERR:

[bam_sort_core] merging from 0 files and 8 in-memory blocks...


STDOUT:



COMMAND: samtools view ./nphase_work/ag_OYL011/Mapped/longReads/ag_OYL011.sorted.header.sam -@ 8 -o ./nphase_work/ag_OYL011/Mapped/longReads/ag_OYL011.sorted.sam

COMMAND: bwa mem -t 8 -M Saccharomyces_cerevisiae.fasta OYL011_S6_L001_R1_001.fastq.gz OYL011_S6_L001_R2_001.fastq.gz > ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.noRG.sam

STDERR:

[M::bwa_idx_load_from_disk] read 0 ALT contigs
[M::process] read 326712 sequences (80000053 bp)...
[M::process] read 326680 sequences (80000010 bp)...
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (2, 145219, 5, 0)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (199, 265, 334)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 604)
[M::mem_pestat] mean and std.dev: (268.41, 104.00)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 739)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 326712 reads in 74.035 CPU sec, 37.054 real sec
[M::process] read 327118 sequences (80000009 bp)...
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (1, 145437, 2, 2)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (199, 265, 334)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 604)
[M::mem_pestat] mean and std.dev: (268.38, 103.73)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 739)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 326680 reads in 132.460 CPU sec, 66.358 real sec
[M::process] read 326932 sequences (80000202 bp)...
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (0, 145758, 3, 2)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (199, 264, 333)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 601)
[M::mem_pestat] mean and std.dev: (267.74, 103.69)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 735)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 327118 reads in 294.026 CPU sec, 147.177 real sec
[M::process] read 325136 sequences (80000456 bp)...
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (0, 145482, 3, 1)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (199, 264, 333)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 601)
[M::mem_pestat] mean and std.dev: (267.54, 103.40)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 735)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 326932 reads in 133.116 CPU sec, 66.673 real sec
[M::process] read 324740 sequences (80000309 bp)...
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (1, 144711, 3, 2)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (200, 266, 335)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 605)
[M::mem_pestat] mean and std.dev: (269.53, 103.64)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 740)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 325136 reads in 85.287 CPU sec, 42.732 real sec
[M::process] read 325134 sequences (80000485 bp)...
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (2, 144406, 1, 3)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (201, 266, 334)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 600)
[M::mem_pestat] mean and std.dev: (269.28, 103.53)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 733)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 324740 reads in 295.813 CPU sec, 148.122 real sec
[M::process] read 325256 sequences (80000206 bp)...
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (2, 144541, 6, 1)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (200, 266, 335)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 605)
[M::mem_pestat] mean and std.dev: (269.32, 103.70)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 740)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 325134 reads in 200.611 CPU sec, 100.449 real sec
[M::process] read 182586 sequences (45013849 bp)...
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (1, 144863, 3, 1)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (200, 266, 335)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 605)
[M::mem_pestat] mean and std.dev: (269.47, 103.99)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 740)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 325256 reads in 80.425 CPU sec, 40.290 real sec
[M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (0, 81287, 3, 2)
[M::mem_pestat] skip orientation FF as there are not enough pairs
[M::mem_pestat] analyzing insert size distribution for orientation FR...
[M::mem_pestat] (25, 50, 75) percentile: (201, 265, 335)
[M::mem_pestat] low and high boundaries for computing mean and std.dev: (1, 603)
[M::mem_pestat] mean and std.dev: (269.58, 103.49)
[M::mem_pestat] low and high boundaries for proper pairs: (1, 737)
[M::mem_pestat] skip orientation RF as there are not enough pairs
[M::mem_pestat] skip orientation RR as there are not enough pairs
[M::mem_process_seqs] Processed 182586 reads in 133.896 CPU sec, 67.060 real sec
[main] Version: 0.7.17-r1188
[main] CMD: bwa mem -t 8 -M Saccharomyces_cerevisiae.fasta OYL011_S6_L001_R1_001.fastq.gz OYL011_S6_L001_R2_001.fastq.gz
[main] Real time: 718.314 sec; CPU: 1431.567 sec


STDOUT is in ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.noRG.sam

COMMAND: gatk AddOrReplaceReadGroups -I ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.noRG.sam -O ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sam -RGID ID_ag_OYL011 -RGLB LB_ag_OYL011 -RGPL ILLUMINA -RGPU PU_ag_OYL011 -RGSM SM_ag_OYL011

STDERR:

20:07:26.140 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
[Wed Dec 14 20:07:26 UTC 2022] AddOrReplaceReadGroups --INPUT ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.noRG.sam --OUTPUT ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sam --RGID ID_ag_OYL011 --RGLB LB_ag_OYL011 --RGPL ILLUMINA --RGPU PU_ag_OYL011 --RGSM SM_ag_OYL011 --VERBOSITY INFO --QUIET false --VALIDATION_STRINGENCY STRICT --COMPRESSION_LEVEL 2 --MAX_RECORDS_IN_RAM 500000 --CREATE_INDEX false --CREATE_MD5_FILE false --GA4GH_CLIENT_SECRETS client_secrets.json --help false --version false --showHidden false --USE_JDK_DEFLATER false --USE_JDK_INFLATER false
[Wed Dec 14 20:07:27 UTC 2022] Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux 5.10.155-138.670.amzn2.x86_64 amd64; OpenJDK 64-Bit Server VM 11.0.1+13-LTS; Deflater: Intel; Inflater: Intel; Provider GCS is available; Picard version: Version:4.3.0.0
INFO	2022-12-14 20:07:27	AddOrReplaceReadGroups	Created read-group ID=ID_ag_OYL011 PL=ILLUMINA LB=LB_ag_OYL011 SM=SM_ag_OYL011

INFO	2022-12-14 20:07:28	AddOrReplaceReadGroups	Seen many non-increasing record positions. Printing Read-names as well.
INFO	2022-12-14 20:08:00	AddOrReplaceReadGroups	Processed     1,000,000 records.  Elapsed time: 00:00:32s.  Time for last 1,000,000:   32s.  Last read position: chrXIII:141,583.  Last read name: M06553:49:000000000-K2W7W:1:1114:6450:6718
INFO	2022-12-14 20:08:29	AddOrReplaceReadGroups	Processed     2,000,000 records.  Elapsed time: 00:01:02s.  Time for last 1,000,000:   29s.  Last read position: chrmt:24,675.  Last read name: M06553:49:000000000-K2W7W:1:2108:6936:15882
[Wed Dec 14 20:08:53 UTC 2022] picard.sam.AddOrReplaceReadGroups done. Elapsed time: 1.47 minutes.
Runtime.totalMemory()=325058560
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar AddOrReplaceReadGroups -I ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.noRG.sam -O ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sam -RGID ID_ag_OYL011 -RGLB LB_ag_OYL011 -RGPL ILLUMINA -RGPU PU_ag_OYL011 -RGSM SM_ag_OYL011


STDOUT:

Tool returned:
0


COMMAND: samtools view -@ 8 -bT Saccharomyces_cerevisiae.fasta -q 1 ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sam -o ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.bam

COMMAND: samtools sort ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.bam -@ 8 -o ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.bam

STDERR:

[bam_sort_core] merging from 0 files and 8 in-memory blocks...


STDOUT:



COMMAND: samtools index -@ 8 ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.bam

COMMAND: gatk MarkDuplicates --REMOVE_DUPLICATES true -I ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.bam -O ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.MD.bam -M /dev/null

STDERR:

20:10:25.841 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
[Wed Dec 14 20:10:25 UTC 2022] MarkDuplicates --INPUT ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.bam --OUTPUT ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.MD.bam --METRICS_FILE /dev/null --REMOVE_DUPLICATES true --MAX_SEQUENCES_FOR_DISK_READ_ENDS_MAP 50000 --MAX_FILE_HANDLES_FOR_READ_ENDS_MAP 8000 --SORTING_COLLECTION_SIZE_RATIO 0.25 --TAG_DUPLICATE_SET_MEMBERS false --REMOVE_SEQUENCING_DUPLICATES false --TAGGING_POLICY DontTag --CLEAR_DT true --DUPLEX_UMI false --FLOW_MODE false --FLOW_QUALITY_SUM_STRATEGY false --USE_END_IN_UNPAIRED_READS false --USE_UNPAIRED_CLIPPED_END false --UNPAIRED_END_UNCERTAINTY 0 --FLOW_SKIP_FIRST_N_FLOWS 0 --FLOW_Q_IS_KNOWN_END false --FLOW_EFFECTIVE_QUALITY_THRESHOLD 15 --ADD_PG_TAG_TO_READS true --ASSUME_SORTED false --DUPLICATE_SCORING_STRATEGY SUM_OF_BASE_QUALITIES --PROGRAM_RECORD_ID MarkDuplicates --PROGRAM_GROUP_NAME MarkDuplicates --READ_NAME_REGEX <optimized capture of last three ':' separated fields as numeric values> --OPTICAL_DUPLICATE_PIXEL_DISTANCE 100 --MAX_OPTICAL_DUPLICATE_SET_SIZE 300000 --VERBOSITY INFO --QUIET false --VALIDATION_STRINGENCY STRICT --COMPRESSION_LEVEL 2 --MAX_RECORDS_IN_RAM 500000 --CREATE_INDEX false --CREATE_MD5_FILE false --GA4GH_CLIENT_SECRETS client_secrets.json --help false --version false --showHidden false --USE_JDK_DEFLATER false --USE_JDK_INFLATER false
[Wed Dec 14 20:10:26 UTC 2022] Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux 5.10.155-138.670.amzn2.x86_64 amd64; OpenJDK 64-Bit Server VM 11.0.1+13-LTS; Deflater: Intel; Inflater: Intel; Provider GCS is available; Picard version: Version:4.3.0.0
INFO	2022-12-14 20:10:26	MarkDuplicates	Start of doWork freeMemory: 64347464; totalMemory: 91226112; maxMemory: 2084569088
INFO	2022-12-14 20:10:26	MarkDuplicates	Reading input file and constructing read end information.
INFO	2022-12-14 20:10:26	MarkDuplicates	Will retain up to 7552786 data points before spilling to disk.
INFO	2022-12-14 20:10:33	MarkDuplicates	Read     1,000,000 records.  Elapsed time: 00:00:06s.  Time for last 1,000,000:    6s.  Last read position: chrVIII:114,308
INFO	2022-12-14 20:10:33	MarkDuplicates	Tracking 923 as yet unmatched pairs. 74 records in RAM.
INFO	2022-12-14 20:10:38	MarkDuplicates	Read     2,000,000 records.  Elapsed time: 00:00:11s.  Time for last 1,000,000:    5s.  Last read position: chrXV:76,867
INFO	2022-12-14 20:10:38	MarkDuplicates	Tracking 1537 as yet unmatched pairs. 110 records in RAM.
INFO	2022-12-14 20:10:41	MarkDuplicates	Read 2581301 records. 2353 pairs never matched.
INFO	2022-12-14 20:10:41	MarkDuplicates	After buildSortedReadEndLists freeMemory: 541550472; totalMemory: 904921088; maxMemory: 2084569088
INFO	2022-12-14 20:10:41	MarkDuplicates	Will retain up to 65142784 duplicate indices before spilling to disk.
INFO	2022-12-14 20:10:41	MarkDuplicates	Traversing read pair information and detecting duplicates.
INFO	2022-12-14 20:10:42	MarkDuplicates	Traversing fragment information and detecting duplicates.
INFO	2022-12-14 20:10:43	MarkDuplicates	Sorting list of duplicate records.
INFO	2022-12-14 20:10:43	MarkDuplicates	After generateDuplicateIndexes freeMemory: 367127064; totalMemory: 916455424; maxMemory: 2084569088
INFO	2022-12-14 20:10:43	MarkDuplicates	Marking 57060 records as duplicates.
INFO	2022-12-14 20:10:43	MarkDuplicates	Found 113 optical duplicate clusters.
INFO	2022-12-14 20:10:43	MarkDuplicates	Reads are assumed to be ordered by: coordinate
INFO	2022-12-14 20:10:56	MarkDuplicates	Writing complete. Closing input iterator.
INFO	2022-12-14 20:10:56	MarkDuplicates	Duplicate Index cleanup.
INFO	2022-12-14 20:10:56	MarkDuplicates	Getting Memory Stats.
INFO	2022-12-14 20:10:56	MarkDuplicates	Before output close freeMemory: 69763160; totalMemory: 98566144; maxMemory: 2084569088
INFO	2022-12-14 20:10:56	MarkDuplicates	Closed outputs. Getting more Memory Stats.
INFO	2022-12-14 20:10:56	MarkDuplicates	After output close freeMemory: 66857608; totalMemory: 94371840; maxMemory: 2084569088
[Wed Dec 14 20:10:56 UTC 2022] picard.sam.markduplicates.MarkDuplicates done. Elapsed time: 0.52 minutes.
Runtime.totalMemory()=94371840
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar MarkDuplicates --REMOVE_DUPLICATES true -I ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.bam -O ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.MD.bam -M /dev/null


STDOUT:

Tool returned:
0


COMMAND: samtools sort ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.sorted.MD.bam -@ 8 -o ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.final.bam

STDERR:

[bam_sort_core] merging from 0 files and 8 in-memory blocks...


STDOUT:



COMMAND: samtools index -@ 8 ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.final.bam

COMMAND: gatk HaplotypeCaller -R Saccharomyces_cerevisiae.fasta -ploidy 2 -I ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.final.bam -O ./nphase_work/ag_OYL011/VariantCalls/shortReads/ag_OYL011.vcf

STDERR:

20:11:17.028 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
20:11:17.179 INFO  HaplotypeCaller - ------------------------------------------------------------
20:11:17.179 INFO  HaplotypeCaller - The Genome Analysis Toolkit (GATK) v4.3.0.0
20:11:17.179 INFO  HaplotypeCaller - For support and documentation go to https://software.broadinstitute.org/gatk/
20:11:17.180 INFO  HaplotypeCaller - Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux v5.10.155-138.670.amzn2.x86_64 amd64
20:11:17.180 INFO  HaplotypeCaller - Java runtime: OpenJDK 64-Bit Server VM v11.0.1+13-LTS
20:11:17.180 INFO  HaplotypeCaller - Start Date/Time: December 14, 2022 at 8:11:16 PM UTC
20:11:17.180 INFO  HaplotypeCaller - ------------------------------------------------------------
20:11:17.180 INFO  HaplotypeCaller - ------------------------------------------------------------
20:11:17.181 INFO  HaplotypeCaller - HTSJDK Version: 3.0.1
20:11:17.181 INFO  HaplotypeCaller - Picard Version: 2.27.5
20:11:17.181 INFO  HaplotypeCaller - Built for Spark Version: 2.4.5
20:11:17.181 INFO  HaplotypeCaller - HTSJDK Defaults.COMPRESSION_LEVEL : 2
20:11:17.181 INFO  HaplotypeCaller - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
20:11:17.181 INFO  HaplotypeCaller - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
20:11:17.182 INFO  HaplotypeCaller - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
20:11:17.182 INFO  HaplotypeCaller - Deflater: IntelDeflater
20:11:17.182 INFO  HaplotypeCaller - Inflater: IntelInflater
20:11:17.182 INFO  HaplotypeCaller - GCS max retries/reopens: 20
20:11:17.182 INFO  HaplotypeCaller - Requester pays: disabled
20:11:17.182 INFO  HaplotypeCaller - Initializing engine
20:11:17.400 INFO  HaplotypeCaller - Done initializing engine
20:11:17.413 INFO  HaplotypeCallerEngine - Disabling physical phasing, which is supported only for reference-model confidence output
20:11:17.430 INFO  NativeLibraryLoader - Loading libgkl_utils.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_utils.so
20:11:17.440 INFO  NativeLibraryLoader - Loading libgkl_pairhmm_omp.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_pairhmm_omp.so
20:11:17.468 INFO  IntelPairHmm - Flush-to-zero (FTZ) is enabled when running PairHMM
20:11:17.469 INFO  IntelPairHmm - Available threads: 2
20:11:17.469 INFO  IntelPairHmm - Requested threads: 4
20:11:17.469 WARN  IntelPairHmm - Using 2 available threads, but 4 were requested
20:11:17.469 INFO  PairHMM - Using the OpenMP multi-threaded AVX-accelerated native PairHMM implementation
20:11:17.529 INFO  ProgressMeter - Starting traversal
20:11:17.529 INFO  ProgressMeter -        Current Locus  Elapsed Minutes     Regions Processed   Regions/Minute
20:11:18.171 WARN  InbreedingCoeff - InbreedingCoeff will not be calculated at position chrI:472 and possibly subsequent; at least 10 samples must have called genotypes
20:11:34.286 INFO  ProgressMeter -            chrI:3242              0.3                    20             71.6
20:11:50.691 INFO  ProgressMeter -            chrI:4953              0.6                    40             72.4
20:12:03.823 INFO  ProgressMeter -            chrI:7011              0.8                    60             77.8
20:12:25.167 INFO  ProgressMeter -            chrI:9007              1.1                    80             71.0
...
22:05:55.207 INFO  ProgressMeter -          chrmt:73003            114.6                 90990            793.8
22:06:12.662 INFO  ProgressMeter -          chrmt:77664            114.9                 91020            792.0
22:07:01.748 INFO  ProgressMeter -          chrmt:81262            115.7                 91050            786.7
22:07:17.980 INFO  ProgressMeter -          chrmt:82384            116.0                 91060            784.9
22:07:34.274 INFO  HaplotypeCaller - 15375 read(s) filtered by: MappingQualityReadFilter 
0 read(s) filtered by: MappingQualityAvailableReadFilter 
0 read(s) filtered by: MappedReadFilter 
23544 read(s) filtered by: NotSecondaryAlignmentReadFilter 
0 read(s) filtered by: NotDuplicateReadFilter 
0 read(s) filtered by: PassesVendorQualityCheckReadFilter 
0 read(s) filtered by: NonZeroReferenceLengthAlignmentReadFilter 
0 read(s) filtered by: GoodCigarReadFilter 
0 read(s) filtered by: WellformedReadFilter 
38919 total reads filtered
22:07:34.275 INFO  ProgressMeter -          chrmt:83724            116.3                 91079            783.3
22:07:34.275 INFO  ProgressMeter - Traversal complete. Processed 91079 total regions in 116.3 minutes.
22:07:34.314 INFO  VectorLoglessPairHMM - Time spent in setup for JNI call : 3.627222499
22:07:34.315 INFO  PairHMM - Total compute time in PairHMM computeLogLikelihoods() : 2524.580265775
22:07:34.315 INFO  SmithWatermanAligner - Total compute time in java Smith-Waterman : 3223.87 sec
22:07:34.316 INFO  HaplotypeCaller - Shutting down engine
[December 14, 2022 at 10:07:34 PM UTC] org.broadinstitute.hellbender.tools.walkers.haplotypecaller.HaplotypeCaller done. Elapsed time: 116.29 minutes.
Runtime.totalMemory()=675282944
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar HaplotypeCaller -R Saccharomyces_cerevisiae.fasta -ploidy 2 -I ./nphase_work/ag_OYL011/Mapped/shortReads/ag_OYL011.final.bam -O ./nphase_work/ag_OYL011/VariantCalls/shortReads/ag_OYL011.vcf


STDOUT:



COMMAND: gatk SelectVariants -R Saccharomyces_cerevisiae.fasta --variant ./nphase_work/ag_OYL011/VariantCalls/shortReads/ag_OYL011.vcf -O ./nphase_work/ag_OYL011/VariantCalls/shortReads/ag_OYL011.SNPs.vcf --select-type-to-include SNP

STDERR:

22:07:44.455 INFO  NativeLibraryLoader - Loading libgkl_compression.so from jar:file:/home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar!/com/intel/gkl/native/libgkl_compression.so
22:07:45.122 INFO  SelectVariants - ------------------------------------------------------------
22:07:45.123 INFO  SelectVariants - The Genome Analysis Toolkit (GATK) v4.3.0.0
22:07:45.124 INFO  SelectVariants - For support and documentation go to https://software.broadinstitute.org/gatk/
22:07:45.133 INFO  SelectVariants - Executing as ec2-user@ip-172-31-29-135.us-east-2.compute.internal on Linux v5.10.155-138.670.amzn2.x86_64 amd64
22:07:45.133 INFO  SelectVariants - Java runtime: OpenJDK 64-Bit Server VM v11.0.1+13-LTS
22:07:45.133 INFO  SelectVariants - Start Date/Time: December 14, 2022 at 10:07:44 PM UTC
22:07:45.133 INFO  SelectVariants - ------------------------------------------------------------
22:07:45.133 INFO  SelectVariants - ------------------------------------------------------------
22:07:45.134 INFO  SelectVariants - HTSJDK Version: 3.0.1
22:07:45.135 INFO  SelectVariants - Picard Version: 2.27.5
22:07:45.135 INFO  SelectVariants - Built for Spark Version: 2.4.5
22:07:45.135 INFO  SelectVariants - HTSJDK Defaults.COMPRESSION_LEVEL : 2
22:07:45.135 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_READ_FOR_SAMTOOLS : false
22:07:45.135 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_SAMTOOLS : true
22:07:45.136 INFO  SelectVariants - HTSJDK Defaults.USE_ASYNC_IO_WRITE_FOR_TRIBBLE : false
22:07:45.136 INFO  SelectVariants - Deflater: IntelDeflater
22:07:45.136 INFO  SelectVariants - Inflater: IntelInflater
22:07:45.149 INFO  SelectVariants - GCS max retries/reopens: 20
22:07:45.149 INFO  SelectVariants - Requester pays: disabled
22:07:45.149 INFO  SelectVariants - Initializing engine
22:07:45.821 INFO  FeatureManager - Using codec VCFCodec to read file file:///home/ec2-user/./nphase_work/ag_OYL011/VariantCalls/shortReads/ag_OYL011.vcf
22:07:45.960 INFO  SelectVariants - Done initializing engine
22:07:46.123 INFO  ProgressMeter - Starting traversal
22:07:46.124 INFO  ProgressMeter -        Current Locus  Elapsed Minutes    Variants Processed  Variants/Minute
22:07:54.842 INFO  ProgressMeter -        chrXVI:941337              0.1                 86639         596345.1
22:07:54.842 INFO  ProgressMeter - Traversal complete. Processed 86639 total variants in 0.1 minutes.
22:07:54.880 INFO  SelectVariants - Shutting down engine
[December 14, 2022 at 10:07:54 PM UTC] org.broadinstitute.hellbender.tools.walkers.variantutils.SelectVariants done. Elapsed time: 0.18 minutes.
Runtime.totalMemory()=267386880
Using GATK jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar
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 -jar /home/ec2-user/miniconda3/envs/polyploidPhasing/share/gatk4-4.3.0.0-0/gatk-package-4.3.0.0-local.jar SelectVariants -R Saccharomyces_cerevisiae.fasta --variant ./nphase_work/ag_OYL011/VariantCalls/shortReads/ag_OYL011.vcf -O ./nphase_work/ag_OYL011/VariantCalls/shortReads/ag_OYL011.SNPs.vcf --select-type-to-include SNP


STDOUT:

I'm sorry this is such a long post but I am so confused why it ends the way it does - and consistently every time I run it. I'm going to try and run it with another sample today just to make sure it's not this sample that's giving it grief. Thank you for all your help so far!!!

[OmarOakheart]

So, looking at the output log, you can see that a lot of lines are duplicated, which shouldn't happen and I also presume didn't happen with the example dataset?

Long reads successfully mapped to reference
Removing quality 0 (multimapped) reads, turning to bam and sorting it
Short reads successfully mapped to reference
Identified heterozygous SNPs in short read VCF
Extracted heterozygous SNP info based on short read VCF
Identified heterozygous SNPs in short read VCF
Extracted heterozygous SNP info based on short read VCF
Long reads successfully mapped to reference
Removing quality 0 (multimapped) reads, turning to bam and sorting it
Short reads successfully mapped to reference
Identified heterozygous SNPs in short read VCF
Extracted heterozygous SNP info based on short read VCF

Could you show me what command line you type to launch nPhase? I'm really not seeing a situation that would cause this behavior. Could you also check if when you launch the example dataset it does the same thing of seemingly running the entire pipeline several times in parallel?

[rmormando]

I noticed that too! I thought it was weird! I'm glad I wasn't seeing things...

I used conda to activate polyploidPhasing and then I use this command (with nohup and & so it can continue running on the server without me needing to be logged in:

nohup nphase pipeline --sampleName OYL011 --reference Saccharomyces_cerevisiae.fasta --R1 OYL011_S2_L001_R1_001.fastq.gz --R2 OYL011_S2_L001_R2_001.fastq.gz --longReads OYL-011_passMinQ7.fastq --longReadPlatform ont --output ./nphase_work/ --threads 8 &

When I ran the example dataset it didn't seem to run the pipeline several times either.

[OmarOakheart]

I usually use screen rather than nohup so I'm not familiar with how it proceeds. How do you get the STDOUT, did you just stay logged in? Do you also get the STDERR?

[rmormando]

It writes the STDOUT (and whatever prints to the command line - so I'm assuming the STDERR as well) to a txt file called: nohup.out

It should work the same way as screen? But I could try using that instead and see if that makes a difference.

[OmarOakheart]

I think there's the slightest little chance that STDERR isn't redirected to nohup.out and that it's hiding an error from us that would help us understand what's going on here. I do see the documentation for nohup seems to say that STDERR should be in nohup.out but maybe doing 2>&1 & instead of just & at the end of your command line will give us more information?

Screen is a bit weird to use, if you're not familiar with it.

Sorry this is such trouble, I really don't see what could cause it to run several times in parallel. I suppose I've also never tested running nphase in the background with & but that shouldn't break anything.

I'm thinking there's an error being output that we're not seeing. The example dataset is tiny, so maybe we wouldn't see anything, but did you test it with nohup or without?

[rmormando]

Hi again! I ran it again with the example data using nohup and & and the log files didn't show any signs of duplications in the process. So I'm back to square one and I can't figure out what to do!

Hopefully we can figure this out together - it would be great to use and in case someone else has a problem like this they can use this to help!

[OmarOakheart]

Okay, let's troubleshoot. First making sure we're on the same page.

Initially, the issue was that your machine restarted by accident in the middle of a run and my advice was to run nphase partial. Running nphase partial, for some reason, failed silently.

The example data works without issue, but when you tried to run the entire pipeline (in a new folder, starting over completely), it fails again silently at the same spot.

We also are seeing a weird glitch where the heterozygous SNPs are being extracted twice, as shown in the logs, but it doesn't happen with the example data.

Maybe let's look at the data then and see what's going on. Hopefully you still have the data from the last failed attempt at running nphase pipeline. Do you have a .hetPositions.SNPxLongReads.validated.tsv file in your VariantCalls/longReads folder? Does it show SNPs in chromosomes I to XVI?

[rmormando]

Okay the weirdest thing happened...it worked???

I reran the SAME code last night with my sample and it went all the way through and gave me phased fastq files? I have no idea what was different/what changed but it went all the way through. Maybe it had something to do with the server I was on?

I'm going to use another sample now and see if it runs all the way or stops at the same place but everything you said was right: my machine restarted by accident in the middle of the run, trying to run nphase partial to pick up where it left off failed silently, the example data worked fine with no duplicated processes, but when I go to run it with my data the same errors (pretty much at the same place) come up. Depending on what happens with the next sample maybe it was just something to do with just using & ? The only thing I did differently this time around was use 2>&1 & like you suggested.

Now that I have data I have some questions on how to interpret it. In the resulting /Phased/FastQ folder there are 834 cluster fastq files and 430 merged clusters fastq files. Is that normal for some (yeast) data? I know these are haploTIGs and not full haploTYPEs so how do I combine them into 4 haplotypes if I think the sample is supposed to be tetraploid? Is this where I would go to the Phasing-Toolkit to combine the necessary clusters together to generate the 4 files I am looking for? My next steps with this data would be to take the 4 haplotypes and do a de novo assembly, polish with short reads, and scaffold them to the reference to then do other downstream analysis with the processed data. So my next step would be to take these 834 clusters.fq and combine them into 4 fastq files - I'm just not sure how to do that now.