phyloFlash
phyloFlash copied to clipboard
Published
20 hours ago •
HRGV
HRGV
PhyloFlash.pm hashing error during taxonomic redistribution: Can't use string as a HASH ref while "strict refs" in use
Hello and thanks for the self-contained, all-in-one super tool!
I have generated a database using phyloFlash_makedb.pl based on 16S sequences extracted from genomes as follows:
phyloFlash_makedb.pl \
--silva_file /home/flejzerowicz/softs/phyloflash/wol/SILVA_WOL_DB.fasta \
--CPUs 4 \
--mem 100 \
--sortmerna \
--univec_file /home/flejzerowicz/softs/phyloflash/UniVec
Here's the two first entries for the input:
- SILVA_WOL_DB.fasta (not showing full sequences)
>G000005825_1.164658.166197 k__Bacteria;p__Firmicutes;c__Bacilli;o__Bacillales;f__Bacillaceae;g__Bacillus;s__Bacillus pseudofirmus
AGAGTTTGATCCTGGCTCAGGACGAA...
>G000007385_1.305736.307270 k__Bacteria;p__Proteobacteria;c__Gammaproteobacteria;o__Xanthomonadales;f__Xanthomonadaceae;g__Xanthomonas;s__Xanthomonas oryzae
AGAGTTTGATCCTGGCTCAGAGTGAACGCTGGCGGCAGGCCT...
And here's the output of this build:
[14:18:48] Checking for required tools.
[14:18:48] Using bbmask found at
"/home/flejzerowicz/softs/bbmap/bbmask.sh".
[14:18:48] Using bbduk found at "/home/flejzerowicz/softs/bbmap/bbduk.sh".
[14:18:48] Using bbmap found at "/home/flejzerowicz/softs/bbmap/bbmap.sh".
[14:18:48] Using barrnapHGV found at
"/home/flejzerowicz/softs/phyloflash/barrnap-HGV/bin/barrnap_HGV".
[14:18:48] Using grep found at "/bin/grep".
[14:18:48] Using vsearch found at
"/home/flejzerowicz/softs/vsearch-2.15.0-linux-x86_64/bin/vsearch".
[14:18:48] Using bowtiebuild found at
"/home/flejzerowicz/localperl/bin/bowtie-build".
[14:18:48] All required tools found.
This is phyloFlash_makedb.pl from phyloFlash.pl v3.3b2
[14:18:48] using local copy of univec:
/home/flejzerowicz/softs/phyloflash/UniVec
[14:18:48] using local copy of Silva SSU RefNR:
/home/flejzerowicz/softs/phyloflash/wol/SILVA_WOL_DB.fasta
[14:18:48] unpacking SILVA database
[14:18:48] searching for LSU contamination in SSU RefNR
[14:18:48] running subcommand:
/home/flejzerowicz/softs/phyloflash/barrnap-HGV/bin/barrnap_HGV
--kingdom bac --threads 12 --evalue 1e-10 --gene lsu --reject
0.01 ./WOL/SILVA_SSU.fasta >tmp.barrnap_hits.bac.gff
2>tmp.barrnap_hits.bac.barrnap.out
[14:18:52] running subcommand:
/home/flejzerowicz/softs/phyloflash/barrnap-HGV/bin/barrnap_HGV
--kingdom arch --threads 12 --evalue 1e-10 --gene lsu --reject
0.01 ./WOL/SILVA_SSU.fasta >tmp.barrnap_hits.arch.gff
2>tmp.barrnap_hits.arch.barrnap.out
[14:18:56] running subcommand:
/home/flejzerowicz/softs/phyloflash/barrnap-HGV/bin/barrnap_HGV
--kingdom euk --threads 12 --evalue 1e-10 --gene lsu --reject
0.01 ./WOL/SILVA_SSU.fasta >tmp.barrnap_hits.euk.gff
2>tmp.barrnap_hits.euk.barrnap.out
[14:19:01] Removing sequences with potential LSU contamination
[14:19:01] Number of sequences to skip: 19
[14:19:01] masking low entropy regions in SSU RefNR
[14:19:01] running subcommand:
/home/flejzerowicz/softs/bbmap/bbmask.sh overwrite=t -Xmx50g
threads=12 in=./WOL//SILVA_SSU.noLSU.fasta
out=./WOL//SILVA_SSU.noLSU.masked.fasta minkr=4 maxkr=8 mr=t
minlen=20 minke=4 maxke=8 fastawrap=0
2>tmp.bbmask_mask_repeats.log
[14:19:04] removing UniVec contamination in SSU RefNR
[14:19:04] running subcommand:
/home/flejzerowicz/softs/bbmap/bbduk.sh
ref=/home/flejzerowicz/softs/phyloflash/UniVec overwrite=t
-Xmx50g threads=12 fastawrap=0 ktrim=r ow=t minlength=800
mink=11 hdist=1 in=./WOL//SILVA_SSU.noLSU.masked.fasta
out=./WOL//SILVA_SSU.noLSU.masked.trimmed.fasta
stats=./WOL//SILVA_SSU.noLSU.masked.trimmed.fasta.UniVec_contamination_stats.txt
2>tmp.bbduk_remove_univec.log
[14:19:17] Vsearch v2.5.0+ found, will index database to UDB file
[14:19:17] Indexing ./WOL//SILVA_SSU.noLSU.masked.trimmed.fasta to make
UDB file ./WOL//SILVA_SSU.noLSU.masked.trimmed.udb with
Vsearch
[14:19:17] running subcommand:
/home/flejzerowicz/softs/vsearch-2.15.0-linux-x86_64/bin/vsearch
--threads 12 --notrunclabels --makeudb_usearch
./WOL//SILVA_SSU.noLSU.masked.trimmed.fasta --output
./WOL//SILVA_SSU.noLSU.masked.trimmed.udb
2>tmp.vsearch_make_udb.log
[14:19:24] clustering database
[14:19:24] running subcommand:
/home/flejzerowicz/softs/vsearch-2.15.0-linux-x86_64/bin/vsearch
--cluster_fast ./WOL/SILVA_SSU.noLSU.masked.trimmed.fasta
--id 0.99 --centroids
./WOL/SILVA_SSU.noLSU.masked.trimmed.NR99.fasta
--notrunclabels --threads 12
vsearch v2.15.0_linux_x86_64, 251.6GB RAM, 32 cores
https://github.com/torognes/vsearch
Reading file ./WOL/SILVA_SSU.noLSU.masked.trimmed.fasta 100%
23806514 nt in 15846 seqs, min 801, max 3764, avg 1502
Masking 100%
Sorting by length 100%
Counting k-mers 100%
Clustering 100%
Sorting clusters 100%
Writing clusters 100%
Clusters: 6101 Size min 1, max 169, avg 2.6
Singletons: 3372, 21.3% of seqs, 55.3% of clusters
[14:21:47] creating bbmap reference
[14:21:47] running subcommand:
/home/flejzerowicz/softs/bbmap/bbmap.sh -Xmx50g threads=12
ref=./WOL/SILVA_SSU.noLSU.masked.trimmed.NR99.fixed.fasta
path=./WOL/ 2>tmp.bbmap_index.log
[14:21:52] clustering database
[14:21:52] running subcommand:
/home/flejzerowicz/softs/vsearch-2.15.0-linux-x86_64/bin/vsearch
--cluster_fast
./WOL/SILVA_SSU.noLSU.masked.trimmed.NR99.fasta --id 0.96
--centroids ./WOL/SILVA_SSU.noLSU.masked.trimmed.NR96.fasta
--notrunclabels --threads 12
vsearch v2.15.0_linux_x86_64, 251.6GB RAM, 32 cores
https://github.com/torognes/vsearch
Reading file ./WOL/SILVA_SSU.noLSU.masked.trimmed.NR99.fasta 100%
9177122 nt in 6101 seqs, min 802, max 3764, avg 1504
Masking 100%
Sorting by length 100%
Counting k-mers 100%
Clustering 100%
Sorting clusters 100%
Writing clusters 100%
Clusters: 3768 Size min 1, max 67, avg 1.6
Singletons: 2748, 45.0% of seqs, 72.9% of clusters
[14:22:37] creating bowtie index (for emirge)
[14:22:37] running subcommand:
/home/flejzerowicz/localperl/bin/bowtie-build
./WOL/SILVA_SSU.noLSU.masked.trimmed.NR96.fixed.fasta
./WOL/SILVA_SSU.noLSU.masked.trimmed.NR96.fixed.bt -q
2>tmp.bowtiebuild.log
[14:22:42] Walltime used: 3.90 minutes
[14:22:42] The databases for Silva release WOL are ready for phyloFlash
When running phyloFlash, please provide the location of
the databases with the following option:
-dbhome /home/flejzerowicz/softs/phyloflash/WOL
or add the following line to your .bashrc or .bash_profile:
export
PHYLOFLASH_DBHOME=/home/flejzerowicz/softs/phyloflash/WOL
Now the problem is that I obtain the following error after running this command:
phyloFlash.pl \
-read1 /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1202_R1.fastq.gz \
-read2 /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1202_R2.fastq.gz \
-readlength 150 \
-dbhome /home/flejzerowicz/softs/phyloflash/WOL \
-lib G1202 \
-CPUs 4 \
-clusterid 98 \
-taxlevel 7 \
-sortmerna
Error is Can't use string ("2") as a HASH ref while "strict refs" in use at /home/flejzerowicz/softs/phyloflash/PhyloFlash.pm line 806.
This is phyloFlash v3.3b2
[12:51:22] Using dbhome '/home/flejzerowicz/softs/phyloflash/WOL'
[12:51:22] working on library G1202
[12:51:22] Forward reads
/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1202_R1.fastq.gz
[12:51:22] Reverse reads
/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1202_R2.fastq.gz
[12:51:22] Current operating system linux
[12:51:22] Checking for required tools.
[12:51:22] Using mafft found at "/home/flejzerowicz/softs/bin/mafft".
[12:51:22] Using spades found at
"/home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades.py".
[12:51:22] Using barrnap found at
"/home/flejzerowicz/softs/phyloflash/barrnap-HGV/bin/barrnap_HGV".
[12:51:22] Using sed found at
"/home/flejzerowicz/usr/miniconda3/envs/phyloflash/bin/sed".
[12:51:22] Using vsearch found at
"/home/flejzerowicz/softs/vsearch-2.15.0-linux-x86_64/bin/vsearch".
[12:51:22] Using bbmap found at "/home/flejzerowicz/softs/bbmap/bbmap.sh".
[12:51:22] Using fastaFromBed found at "/opt/bedtools/2.26.0/fastaFromBed".
[12:51:22] Using awk found at "/bin/awk".
[12:51:22] Using reformat found at
"/home/flejzerowicz/softs/bbmap/reformat.sh".
[12:51:22] Using grep found at "/bin/grep".
[12:51:22] Using cat found at "/bin/cat".
[12:51:22] Using plotscript_SVG found at
"/home/flejzerowicz/softs/phyloflash/phyloFlash_plotscript_svg.pl".
[12:51:22] Using nhmmer found at
"/home/flejzerowicz/softs/phyloflash/barrnap-HGV/binaries/linux/nhmmer".
[12:51:22] All required tools found.
[12:51:22] filtering reads with SSU db using minimum identity of 70%
[12:51:22] running subcommand:
/home/flejzerowicz/softs/bbmap/bbmap.sh fast=t minidentity=0.7
-Xmx20g reads=-1 threads=4 po=f outputunmapped=f
path=/home/flejzerowicz/softs/phyloflash/WOL out=G1202.bbmap.sam
outm=G1202.G1202_R1.fastq.gz.SSU.1.fq noheader=t ambiguous=all
build=1
in=/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1202_R1.fastq.gz
bhist=G1202.basecompositionhistogram ihist=G1202.inserthistogram
idhist=G1202.idhistogram scafstats=G1202.hitstats overwrite=t
outm2=G1202.G1202_R1.fastq.gz.SSU.2.fq pairlen=1200
in2=/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1202_R2.fastq.gz
2>G1202.bbmap.out
[12:51:53] done...
[12:51:53] Reading SAM file G1202.bbmap.sam into memory
[12:51:53] Writing fixed SAM file to G1202.G1202_R1.fastq.gz.SSU.sam
[12:51:53] Done
[12:51:53] Total read segments processed: 9219574
[12:51:53] insert size median: 176
[12:51:53] insert size std deviation: 72
[12:51:53] Summarizing taxonomy from mapping hits to SILVA database
Can't use string ("2") as a HASH ref while "strict refs" in use at /home/flejzerowicz/softs/phyloflash/PhyloFlash.pm line 806.
However, this database seems to work fine as it served to classify another sample:
This is phyloFlash v3.3b2
[12:45:29] Using dbhome '/home/flejzerowicz/softs/phyloflash/WOL'
[12:45:29] working on library G1201
[12:45:29] Forward reads
/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1201_R1.fastq.gz
[12:45:29] Reverse reads
/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1201_R2.fastq.gz
[12:45:29] Current operating system linux
[12:45:29] Checking for required tools.
[12:45:29] Using sed found at
"/home/flejzerowicz/usr/miniconda3/envs/phyloflash/bin/sed".
[12:45:29] Using cat found at "/bin/cat".
[12:45:29] Using bbmap found at "/home/flejzerowicz/softs/bbmap/bbmap.sh".
[12:45:29] Using fastaFromBed found at "/opt/bedtools/2.26.0/fastaFromBed".
[12:45:29] Using barrnap found at
"/home/flejzerowicz/softs/phyloflash/barrnap-HGV/bin/barrnap_HGV".
[12:45:29] Using nhmmer found at
"/home/flejzerowicz/softs/phyloflash/barrnap-HGV/binaries/linux/nhmmer".
[12:45:29] Using mafft found at "/home/flejzerowicz/softs/bin/mafft".
[12:45:29] Using reformat found at
"/home/flejzerowicz/softs/bbmap/reformat.sh".
[12:45:29] Using vsearch found at
"/home/flejzerowicz/softs/vsearch-2.15.0-linux-x86_64/bin/vsearch".
[12:45:29] Using plotscript_SVG found at
"/home/flejzerowicz/softs/phyloflash/phyloFlash_plotscript_svg.pl".
[12:45:29] Using grep found at "/bin/grep".
[12:45:29] Using awk found at "/bin/awk".
[12:45:29] Using spades found at
"/home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades.py".
[12:45:29] All required tools found.
[12:45:29] filtering reads with SSU db using minimum identity of 70%
[12:45:29] running subcommand:
/home/flejzerowicz/softs/bbmap/bbmap.sh fast=t minidentity=0.7
-Xmx20g reads=-1 threads=4 po=f outputunmapped=f
path=/home/flejzerowicz/softs/phyloflash/WOL out=G1201.bbmap.sam
outm=G1201.G1201_R1.fastq.gz.SSU.1.fq noheader=t ambiguous=all
build=1
in=/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1201_R1.fastq.gz
bhist=G1201.basecompositionhistogram ihist=G1201.inserthistogram
idhist=G1201.idhistogram scafstats=G1201.hitstats overwrite=t
outm2=G1201.G1201_R1.fastq.gz.SSU.2.fq pairlen=1200
in2=/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G1201_R2.fastq.gz
2>G1201.bbmap.out
[12:45:37] done...
[12:45:37] Reading SAM file G1201.bbmap.sam into memory
[12:45:37] Writing fixed SAM file to G1201.G1201_R1.fastq.gz.SSU.sam
[12:45:37] Done
[12:45:37] Total read segments processed: 454748
[12:45:37] insert size median: 188
[12:45:37] insert size std deviation: 98
[12:45:37] Summarizing taxonomy from mapping hits to SILVA database
[12:45:37] done...
[12:45:37] Forward read segments mapping: 922
[12:45:37] Reverse read segments mapping: 942
[12:45:37] Reporting mapping statistics for paired end input
[12:45:37] Total read pairs with at least one segment mapping: 435
[12:45:37] => both segments mapping to same reference: 373
[12:45:37] => both segments mapping to different references: 50
[12:45:37] Read segments where next segment unmapped: 86
[12:45:37] mapping rate: 0.191%
[12:45:37] creating phylotypes with SPAdes
[12:45:37] kmers for SPAdes are 99,111,127
[12:45:37] running subcommand:
/home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades.py -o
G1201.spades -t 4 -m 20 -k 99,111,127 -1
G1201.G1201_R1.fastq.gz.SSU.1.fq -2
G1201.G1201_R1.fastq.gz.SSU.2.fq >G1201.spades.out 2>&1
[12:45:48] Tool execution failed!.
Error was 'Inappropriate ioctl for device' and return code '256'
[12:45:48] done...
[12:45:48] writing final files...
[12:45:48] exporting results to csv
[12:45:48] generating graphics for report in SVG format
[12:45:48] Plotting mapping ID histogram
[12:45:48] running subcommand:
/home/flejzerowicz/softs/phyloflash/phyloFlash_plotscript_svg.pl
--hist G1201.idhistogram --title="Mapping identity (%)"
>G1201.plotscript.out 2>&1
[12:45:48] Plotting piechart of mapping ratios
[12:45:48] running subcommand:
/home/flejzerowicz/softs/phyloflash/phyloFlash_plotscript_svg.pl
-pie G1201.mapratio.csv -title="0.191 % pairs mapped"
>G1201.plotscript.out 2>&1
[12:45:48] Plotting histogram of insert sizes
[12:45:48] running subcommand:
/home/flejzerowicz/softs/phyloflash/phyloFlash_plotscript_svg.pl
--hist G1201.inserthistogram --title="Insert size (bp)"
>G1201.plotscript.out 2>&1
[12:45:48] Plotting barplot of taxonomic summary
[12:45:48] running subcommand:
/home/flejzerowicz/softs/phyloflash/phyloFlash_plotscript_svg.pl
-bar G1201.phyloFlash.NTUabundance.csv -title="Taxonomic summary
from reads mapped" >G1201.plotscript.out 2>&1
[12:45:48] done
[12:45:48] Generating HTML-formatted report and graphics ...
[12:45:48] Cleaning temp files...
[12:45:48] Walltime used: 0.32 minutes with 4 CPU cores
[12:45:48] Thank you for using phyloFlash
You can find your results in G1201.*,
Your main result file is G1201.phyloFlash
Thank you so much for any clue. Franck
Note I have closed by mistake as I needed to heavily edit my message
hello @FranckLejzerowicz thanks for reporting this issue. My hunch is that perhaps some of the taxon strings were not parsed properly but this wasn't picked up in the DB build stage. Could you update phyloFlash to the latest version (3.3b4) and see if the error still occurs? If so, you might have to send us the mapping file (G1202.G1202_R1.fastq.gz.SSU.sam) or the DB file that you used to have a look.
I have an unrelated question, @kbseah Franck noted that his second run worked, and I noticed that he had an error in his log: [12:45:37] kmers for SPAdes are 99,111,127 [12:45:37] running subcommand: /home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades.py -o G1201.spades -t 4 -m 20 -k 99,111,127 -1 G1201.G1201_R1.fastq.gz.SSU.1.fq -2 G1201.G1201_R1.fastq.gz.SSU.2.fq >G1201.spades.out 2>&1 [12:45:48] Tool execution failed!. Error was 'Inappropriate ioctl for device' and return code '256' [12:45:48] done... Is this a common error that pops up for phyloflash, but ultimately does not impact the final output? I'm curious because I have run into the same issue, but I always have the desired output files.
Thanks for spotting this @lielbe , I didn't notice it earlier.
If @FranckLejzerowicz can confirm, this is probably caused by there not being any full-length sequences assembled by SPAdes. Will have to work on getting a more informative error message there...
@kbseah I suspect this is the case, as I have noticed that I do not have any full-length assemblies whenever this error pops up. Not an issue, just double checking that I'm not ignoring a problem within spades.
@lielbe Nice observation! @kbseah is right, but it seems Spades did not complete silently for there not being any full-length sequences assembled: the error message seems to indicate a skewed kmer coverage distribution. I suppose this could be expected as the few 16S detected in a metagenome might be from conserved regions, leaving less reads mapping to adjacent variable regions. I believe this would indeed skew the coverage as reads would concentrate on these conserved regions instead of being mapped more uniformly all along the full assembled 16S sequence, isn't it?
Below, the spades.out for this sample this point to this issue. @kbseah: if my point makes sense, do you think a step to scale down the mappings on conserved regions would solve the issue (for the assembly step)?
Command line: /home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades.py -o /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades -t 4 -m 20 -k 99,111,127 -1 /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.1.fq -2 /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.2.fq
System information:
SPAdes version: 3.13.0
Python version: 3.6.11
OS: Linux-3.10.0-693.17.1.el7.x86_64-x86_64-with-centos-7.4.1708-Core
Output dir: /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades
Mode: read error correction and assembling
Debug mode is turned OFF
Dataset parameters:
Multi-cell mode (you should set '--sc' flag if input data was obtained with MDA (single-cell) technology or --meta flag if processing metagenomic dataset)
Reads:
Library number: 1, library type: paired-end
orientation: fr
left reads: ['/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.1.fq']
right reads: ['/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.2.fq']
interlaced reads: not specified
single reads: not specified
merged reads: not specified
Read error correction parameters:
Iterations: 1
PHRED offset will be auto-detected
Corrected reads will be compressed
Assembly parameters:
k: [99, 111, 127]
Repeat resolution is enabled
Mismatch careful mode is turned OFF
MismatchCorrector will be SKIPPED
Coverage cutoff is turned OFF
Other parameters:
Dir for temp files: /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/tmp
Threads: 4
Memory limit (in Gb): 20
======= SPAdes pipeline started. Log can be found here: /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/spades.log
===== Read error correction started.
== Running read error correction tool: /home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades-hammer /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/corrected/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 75) Starting BayesHammer, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
0:00:00.000 4M / 4M INFO General (main.cpp : 76) Loading config from /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/corrected/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 78) Maximum # of threads to use (adjusted due to OMP capabilities): 4
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 20 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 86) Trying to determine PHRED offset
0:00:00.000 4M / 4M INFO General (main.cpp : 92) Determined value is 33
0:00:00.001 4M / 4M INFO General (hammer_tools.cpp : 36) Hamming graph threshold tau=1, k=21, subkmer positions = [ 0 10 ]
0:00:00.001 4M / 4M INFO General (main.cpp : 113) Size of aux. kmer data 24 bytes
=== ITERATION 0 begins ===
0:00:00.011 4M / 4M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:00.011 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 4 threads. This might take a while.
0:00:00.014 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:00.014 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66634 Gb
0:00:00.014 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 1048576
0:00:00.014 3G / 3G INFO K-mer Splitting (kmer_data.cpp : 97) Processing /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.1.fq
0:00:00.505 3G / 3G INFO K-mer Splitting (kmer_data.cpp : 97) Processing /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.2.fq
0:00:00.691 3G / 3G INFO K-mer Splitting (kmer_data.cpp : 112) Total 1018 reads processed
0:00:00.694 16M / 3G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:00.930 16M / 3G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 66960 kmers in total.
0:00:00.930 16M / 3G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:01.037 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:01.054 16M / 3G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:00:01.133 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 39960 bytes occupied (4.77419 bits per kmer).
0:00:01.135 16M / 3G INFO K-mer Counting (kmer_data.cpp : 356) Arranging kmers in hash map order
0:00:01.141 16M / 3G INFO General (main.cpp : 148) Clustering Hamming graph.
0:00:01.198 16M / 3G INFO General (main.cpp : 155) Extracting clusters
0:00:01.223 16M / 3G INFO General (main.cpp : 167) Clustering done. Total clusters: 46502
0:00:01.223 16M / 3G INFO K-mer Counting (kmer_data.cpp : 376) Collecting K-mer information, this takes a while.
0:00:01.224 16M / 3G INFO K-mer Counting (kmer_data.cpp : 382) Processing /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.1.fq
0:00:01.238 16M / 3G INFO K-mer Counting (kmer_data.cpp : 382) Processing /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.2.fq
0:00:01.252 16M / 3G INFO K-mer Counting (kmer_data.cpp : 389) Collection done, postprocessing.
0:00:01.252 16M / 3G INFO K-mer Counting (kmer_data.cpp : 403) There are 66960 kmers in total. Among them 32446 (48.4558%) are singletons.
0:00:01.252 16M / 3G INFO General (main.cpp : 173) Subclustering Hamming graph
0:00:01.267 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 649) Subclustering done. Total 6 non-read kmers were generated.
0:00:01.267 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 650) Subclustering statistics:
0:00:01.267 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 651) Total singleton hamming clusters: 37984. Among them 25856 (68.0708%) are good
0:00:01.267 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 652) Total singleton subclusters: 1830. Among them 1830 (100%) are good
0:00:01.267 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 653) Total non-singleton subcluster centers: 9665. Among them 7964 (82.4004%) are good
0:00:01.267 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 654) Average size of non-trivial subcluster: 2.99865 kmers
0:00:01.267 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 655) Average number of sub-clusters per non-singleton cluster: 1.3495
0:00:01.268 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 656) Total solid k-mers: 35650
0:00:01.268 16M / 3G INFO Hamming Subclustering (kmer_cluster.cpp : 657) Substitution probabilities: [4,4]((0.935218,0.0141258,0.0346313,0.0160246),(0.0163113,0.945329,0.00635067,0.032009),(0.0286851,0.0058949,0.947243,0.0181768),(0.0137842,0.0310056,0.0120889,0.943121))
0:00:01.269 16M / 3G INFO General (main.cpp : 178) Finished clustering.
0:00:01.269 16M / 3G INFO General (main.cpp : 197) Starting solid k-mers expansion in 4 threads.
0:00:01.275 16M / 3G INFO General (main.cpp : 218) Solid k-mers iteration 0 produced 4011 new k-mers.
0:00:01.281 16M / 3G INFO General (main.cpp : 218) Solid k-mers iteration 1 produced 158 new k-mers.
0:00:01.286 16M / 3G INFO General (main.cpp : 218) Solid k-mers iteration 2 produced 0 new k-mers.
0:00:01.286 16M / 3G INFO General (main.cpp : 222) Solid k-mers finalized
0:00:01.286 16M / 3G INFO General (hammer_tools.cpp : 220) Starting read correction in 4 threads.
0:00:01.287 16M / 3G INFO General (hammer_tools.cpp : 233) Correcting pair of reads: /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.1.fq and /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.G1201_R1.fastq.gz.SSU.2.fq
0:00:01.308 48M / 3G INFO General (hammer_tools.cpp : 168) Prepared batch 0 of 509 reads.
0:00:01.317 48M / 3G INFO General (hammer_tools.cpp : 175) Processed batch 0
0:00:01.338 48M / 3G INFO General (hammer_tools.cpp : 185) Written batch 0
0:00:01.348 16M / 3G INFO General (hammer_tools.cpp : 274) Correction done. Changed 325 bases in 213 reads.
0:00:01.348 16M / 3G INFO General (hammer_tools.cpp : 275) Failed to correct 0 bases out of 147026.
0:00:01.349 16M / 3G INFO General (main.cpp : 255) Saving corrected dataset description to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/corrected/corrected.yaml
0:00:01.352 16M / 3G INFO General (main.cpp : 262) All done. Exiting.
== Compressing corrected reads (with pigz)
== Dataset description file was created: /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/corrected/corrected.yaml
===== Read error correction finished.
===== Assembling started.
== Running assembler: K99
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/K99/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 20 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/dataset.info) with K=99
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 4
0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.000 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.008 4M / 4M INFO General (read_converter.hpp : 77) Converting reads to binary format for library #0 (takes a while)
0:00:00.008 4M / 4M INFO General (read_converter.hpp : 78) Converting paired reads
0:00:00.075 68M / 84M INFO General (binary_converter.hpp : 117) 508 reads written
0:00:00.075 4M / 84M INFO General (read_converter.hpp : 87) Converting single reads
0:00:00.188 132M / 164M INFO General (binary_converter.hpp : 117) 1 reads written
0:00:00.189 4M / 164M INFO General (read_converter.hpp : 95) Converting merged reads
0:00:00.298 132M / 164M INFO General (binary_converter.hpp : 117) 0 reads written
0:00:00.312 4M / 164M INFO General (construction.cpp : 111) Max read length 151
0:00:00.312 4M / 164M INFO General (construction.cpp : 117) Average read length 144.42
0:00:00.312 4M / 164M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.314 4M / 164M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 4 threads. This might take a while.
0:00:00.316 4M / 164M INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:00.316 4M / 164M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66634 Gb
0:00:00.316 4M / 164M INFO General (kmer_splitters.hpp : 97) Using cell size of 1048576
0:00:00.465 2G / 2G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:00.466 16M / 2G INFO General (kmer_splitters.hpp : 308) Used 2034 reads
0:00:00.466 16M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:00.526 16M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 26686 kmers in total.
0:00:00.526 16M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:00.583 16M / 2G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:00.585 16M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:00.585 16M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 4 threads. This might take a while.
0:00:00.588 16M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:00.588 16M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66536 Gb
0:00:00.588 16M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144
0:00:01.061 3G / 3G INFO General (kmer_splitters.hpp : 380) Processed 26686 kmers
0:00:01.061 3G / 3G INFO General (kmer_splitters.hpp : 385) Used 26686 kmers.
0:00:01.063 16M / 3G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:01.272 16M / 3G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 27021 kmers in total.
0:00:01.272 16M / 3G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:01.383 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:01.398 16M / 3G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:00:01.437 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21560 bytes occupied (6.38318 bits per kmer).
0:00:01.437 16M / 3G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:00:01.439 16M / 3G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:00:01.440 16M / 3G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:00:01.440 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:00:01.445 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 752 sequences extracted
0:00:01.447 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:00:01.448 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:00:01.449 16M / 3G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:00:01.449 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:01.449 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:01.455 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 14520 bytes occupied (4.35284 bits per kmer).
0:00:01.455 16M / 3G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:00:01.457 16M / 3G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:00:01.459 16M / 3G INFO General (construction.cpp : 464) Processed 1504 edges
0:00:01.463 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:00:01.463 16M / 3G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 13
0:00:01.463 16M / 3G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 14
0:00:01.463 16M / 3G WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable
0:00:01.463 16M / 3G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 14. Coverage mad: 12.4043
0:00:01.463 16M / 3G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:00:01.465 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:00:01.470 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:00:01.478 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:00:01.494 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:00:01.525 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 32
0:00:01.586 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 64
0:00:01.695 16M / 3G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 8.02213. Fitted coverage std. dev: 2.25083
0:00:01.695 16M / 3G WARN General (kmer_coverage_model.cpp : 327) Valley value was estimated improperly, reset to 5
0:00:01.695 16M / 3G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.999994
0:00:01.695 16M / 3G WARN General (kmer_coverage_model.cpp : 366) Failed to determine erroneous kmer threshold. Threshold set to: 5
0:00:01.695 16M / 3G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 1085
0:00:01.695 16M / 3G INFO General (genomic_info_filler.cpp : 114) Failed to estimate mean coverage
0:00:01.695 16M / 3G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 5
0:00:01.695 16M / 3G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:00:01.695 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:00:01.695 16M / 3G INFO General (graph_pack.hpp : 101) Index refill
0:00:01.702 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:01.702 16M / 3G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 4 threads. This might take a while.
0:00:01.705 16M / 3G INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:01.705 16M / 3G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66536 Gb
0:00:01.705 16M / 3G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144
0:00:02.305 3G / 3G INFO General (edge_index_builders.hpp : 77) Processed 1504 edges
0:00:02.306 3G / 3G INFO General (edge_index_builders.hpp : 82) Used 1504 sequences.
0:00:02.308 16M / 3G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:02.525 16M / 3G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 26686 kmers in total.
0:00:02.525 16M / 3G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:02.661 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:02.675 16M / 3G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:00:02.712 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21384 bytes occupied (6.41055 bits per kmer).
0:00:02.712 16M / 3G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:00:02.714 16M / 3G INFO General (edge_index.hpp : 92) Index refilled
0:00:02.715 16M / 3G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:00:02.715 16M / 3G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:00:02.716 16M / 3G INFO General (gap_closer.cpp : 138) Used 508 paired reads
0:00:02.716 16M / 3G INFO General (gap_closer.cpp : 140) Merging paired indices
0:00:02.717 16M / 3G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:00:02.719 16M / 3G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 13 gaps after checking 61 candidates
0:00:02.720 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:00:02.721 16M / 3G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:00:02.721 16M / 3G INFO General (simplification.cpp : 68) Most init cleaning disabled since detected mean 0 was less than activation coverage 10
0:00:02.721 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:00:02.722 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:00:02.723 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:00:02.723 16M / 3G INFO General (simplification.cpp : 357) Graph simplification started
0:00:02.723 16M / 3G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:00:02.723 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:00:02.723 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.724 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 212 times
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.725 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.725 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.725 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.726 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.726 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.726 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.726 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.726 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.727 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.727 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.727 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.727 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:00:02.727 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.728 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.728 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.730 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.730 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.730 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.730 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:00:02.730 16M / 3G INFO General (graph_pack.hpp : 101) Index refill
0:00:02.735 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:02.735 16M / 3G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 4 threads. This might take a while.
0:00:02.737 16M / 3G INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:02.737 16M / 3G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66536 Gb
0:00:02.737 16M / 3G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144
0:00:03.261 3G / 3G INFO General (edge_index_builders.hpp : 82) Used 644 sequences.
0:00:03.263 16M / 3G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:03.478 16M / 3G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 22155 kmers in total.
0:00:03.478 16M / 3G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:03.580 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:03.594 16M / 3G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:00:03.676 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 19208 bytes occupied (6.93586 bits per kmer).
0:00:03.679 16M / 3G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:00:03.681 16M / 3G INFO General (edge_index.hpp : 92) Index refilled
0:00:03.681 16M / 3G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:00:03.682 16M / 3G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:00:03.683 16M / 3G INFO General (gap_closer.cpp : 138) Used 508 paired reads
0:00:03.683 16M / 3G INFO General (gap_closer.cpp : 140) Merging paired indices
0:00:03.684 16M / 3G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:00:03.685 16M / 3G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 1 gaps after checking 33 candidates
0:00:03.687 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:00:03.687 16M / 3G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:00:03.687 16M / 3G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:00:03.687 16M / 3G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:00:03.687 16M / 3G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:00:03.687 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:03.687 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:03.687 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:03.688 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:03.688 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:03.688 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:03.688 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:03.688 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:03.688 16M / 3G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:00:03.688 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:00:03.698 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 301 times
0:00:03.698 16M / 3G INFO General (simplification.cpp : 470) Counting average coverage
0:00:03.698 16M / 3G INFO General (simplification.cpp : 476) Average coverage = 2.36386
0:00:03.698 16M / 3G WARN General (simplification.cpp : 479) The determined erroneous connection coverage threshold may be determined improperly
0:00:03.698 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:00:03.698 16M / 3G INFO General (contig_output_stage.cpp : 40) Writing GFA to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/assembly_graph_with_scaffolds.gfa
0:00:03.700 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/before_rr.fasta
0:00:03.705 16M / 3G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/assembly_graph.fastg
0:00:03.711 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/simplified_contigs.fasta
0:00:03.717 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/final_contigs.fasta
0:00:03.721 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:00:03.721 16M / 3G INFO General (contig_output_stage.cpp : 40) Writing GFA to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/assembly_graph_with_scaffolds.gfa
0:00:03.724 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/before_rr.fasta
0:00:03.727 16M / 3G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/assembly_graph.fastg
0:00:03.732 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/simplified_contigs.fasta
0:00:03.736 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K99/final_contigs.fasta
0:00:03.743 16M / 3G INFO General (launch.hpp : 149) SPAdes finished
0:00:03.747 16M / 3G INFO General (main.cpp : 109) Assembling time: 0 hours 0 minutes 3 seconds
Max read length detected as 151
== Running assembler: K111
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/K111/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 20 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/dataset.info) with K=111
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 4
0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.000 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.003 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.003 4M / 4M INFO General (construction.cpp : 111) Max read length 151
0:00:00.003 4M / 4M INFO General (construction.cpp : 117) Average read length 144.42
0:00:00.003 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.006 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 4 threads. This might take a while.
0:00:00.008 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:00.008 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66634 Gb
0:00:00.008 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 1048576
0:00:00.128 2G / 2G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:00.172 16M / 2G INFO General (kmer_splitters.hpp : 308) Used 2034 reads
0:00:00.172 16M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:00.226 16M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 22935 kmers in total.
0:00:00.227 16M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:00.272 16M / 2G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:00.274 16M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:00.274 16M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 4 threads. This might take a while.
0:00:00.276 16M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:00.276 16M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66536 Gb
0:00:00.276 16M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144
0:00:00.732 3G / 3G INFO General (kmer_splitters.hpp : 380) Processed 22935 kmers
0:00:00.732 3G / 3G INFO General (kmer_splitters.hpp : 385) Used 22935 kmers.
0:00:00.734 16M / 3G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:00.950 16M / 3G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 23294 kmers in total.
0:00:00.950 16M / 3G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:01.049 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:01.065 16M / 3G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:00:01.103 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 19800 bytes occupied (6.80003 bits per kmer).
0:00:01.103 16M / 3G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:00:01.107 16M / 3G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:00:01.108 16M / 3G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:00:01.108 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:00:01.112 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 661 sequences extracted
0:00:01.115 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:00:01.116 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:00:01.117 16M / 3G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:00:01.117 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:01.117 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:01.123 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 12816 bytes occupied (4.47037 bits per kmer).
0:00:01.123 16M / 3G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:00:01.125 16M / 3G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:00:01.126 16M / 3G INFO General (construction.cpp : 464) Processed 1322 edges
0:00:01.130 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:00:01.130 16M / 3G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 10
0:00:01.130 16M / 3G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 11
0:00:01.130 16M / 3G WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable
0:00:01.130 16M / 3G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 11. Coverage mad: 10.9953
0:00:01.130 16M / 3G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:00:01.131 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:00:01.134 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:00:01.141 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:00:01.154 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:00:01.183 16M / 3G INFO General (kmer_coverage_model.cpp : 295) ... iteration 32
0:00:01.215 16M / 3G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 4. Fitted coverage std. dev: 7.06509e-30
0:00:01.215 16M / 3G WARN General (kmer_coverage_model.cpp : 327) Valley value was estimated improperly, reset to 2
0:00:01.215 16M / 3G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1
0:00:01.215 16M / 3G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 4
0:00:01.215 16M / 3G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 3
0:00:01.215 16M / 3G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 2843
0:00:01.215 16M / 3G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 4
0:00:01.215 16M / 3G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 3
0:00:01.215 16M / 3G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:00:01.215 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:00:01.215 16M / 3G INFO General (graph_pack.hpp : 101) Index refill
0:00:01.220 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:01.220 16M / 3G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 4 threads. This might take a while.
0:00:01.222 16M / 3G INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:01.222 16M / 3G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66536 Gb
0:00:01.222 16M / 3G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144
0:00:01.688 3G / 3G INFO General (edge_index_builders.hpp : 77) Processed 1322 edges
0:00:01.688 3G / 3G INFO General (edge_index_builders.hpp : 82) Used 1322 sequences.
0:00:01.691 16M / 3G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:01.910 16M / 3G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 22935 kmers in total.
0:00:01.910 16M / 3G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:02.013 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:02.026 16M / 3G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:00:02.065 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 19616 bytes occupied (6.84229 bits per kmer).
0:00:02.066 16M / 3G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:00:02.067 16M / 3G INFO General (edge_index.hpp : 92) Index refilled
0:00:02.068 16M / 3G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:00:02.068 16M / 3G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:00:02.069 16M / 3G INFO General (gap_closer.cpp : 138) Used 508 paired reads
0:00:02.069 16M / 3G INFO General (gap_closer.cpp : 140) Merging paired indices
0:00:02.070 16M / 3G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:00:02.072 16M / 3G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 7 gaps after checking 52 candidates
0:00:02.073 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:00:02.073 16M / 3G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:00:02.073 16M / 3G INFO General (simplification.cpp : 68) Most init cleaning disabled since detected mean 4 was less than activation coverage 10
0:00:02.073 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:00:02.073 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:00:02.073 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:00:02.074 16M / 3G INFO General (simplification.cpp : 357) Graph simplification started
0:00:02.074 16M / 3G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:00:02.074 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:00:02.074 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.075 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 153 times
0:00:02.075 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.075 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.075 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.075 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.076 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.076 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.076 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.077 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.077 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.077 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.077 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.077 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.077 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.077 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.077 16M / 3G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:00:02.077 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.078 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.078 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.078 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.078 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:00:02.078 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:00:02.078 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:00:02.078 16M / 3G INFO General (graph_pack.hpp : 101) Index refill
0:00:02.083 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:02.083 16M / 3G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 4 threads. This might take a while.
0:00:02.085 16M / 3G INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:02.085 16M / 3G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66536 Gb
0:00:02.085 16M / 3G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144
0:00:02.550 3G / 3G INFO General (edge_index_builders.hpp : 82) Used 704 sequences.
0:00:02.553 16M / 3G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:02.771 16M / 3G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 20627 kmers in total.
0:00:02.771 16M / 3G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:02.917 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:02.930 16M / 3G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:00:02.971 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 18544 bytes occupied (7.19213 bits per kmer).
0:00:02.974 16M / 3G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:00:02.976 16M / 3G INFO General (edge_index.hpp : 92) Index refilled
0:00:02.976 16M / 3G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:00:02.977 16M / 3G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:00:02.978 16M / 3G INFO General (gap_closer.cpp : 138) Used 508 paired reads
0:00:02.978 16M / 3G INFO General (gap_closer.cpp : 140) Merging paired indices
0:00:02.978 16M / 3G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:00:02.980 16M / 3G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 1 gaps after checking 37 candidates
0:00:02.981 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:00:02.981 16M / 3G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:00:02.981 16M / 3G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:00:02.981 16M / 3G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:00:02.981 16M / 3G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:00:02.981 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.981 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.981 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.981 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.982 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:00:02.982 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:00:02.982 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:00:02.982 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:00:02.982 16M / 3G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:00:02.982 16M / 3G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:00:02.991 16M / 3G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 329 times
0:00:02.991 16M / 3G INFO General (simplification.cpp : 470) Counting average coverage
0:00:02.991 16M / 3G INFO General (simplification.cpp : 476) Average coverage = 1.81956
0:00:02.991 16M / 3G WARN General (simplification.cpp : 479) The determined erroneous connection coverage threshold may be determined improperly
0:00:02.991 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:00:02.991 16M / 3G INFO General (contig_output_stage.cpp : 40) Writing GFA to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/assembly_graph_with_scaffolds.gfa
0:00:02.994 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/before_rr.fasta
0:00:02.997 16M / 3G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/assembly_graph.fastg
0:00:03.001 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/simplified_contigs.fasta
0:00:03.004 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/final_contigs.fasta
0:00:03.008 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:00:03.009 16M / 3G INFO General (contig_output_stage.cpp : 40) Writing GFA to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/assembly_graph_with_scaffolds.gfa
0:00:03.012 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/before_rr.fasta
0:00:03.015 16M / 3G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/assembly_graph.fastg
0:00:03.020 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/simplified_contigs.fasta
0:00:03.024 16M / 3G INFO General (contig_output.hpp : 22) Outputting contigs to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades//K111/final_contigs.fasta
0:00:03.032 16M / 3G INFO General (launch.hpp : 149) SPAdes finished
0:00:03.035 16M / 3G INFO General (main.cpp : 109) Assembling time: 0 hours 0 minutes 3 seconds
== Running assembler: K127
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/K127/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 20 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/dataset.info) with K=127
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 4
0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.000 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.003 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.003 4M / 4M INFO General (construction.cpp : 111) Max read length 151
0:00:00.003 4M / 4M INFO General (construction.cpp : 117) Average read length 144.42
0:00:00.003 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.006 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 4 threads. This might take a while.
0:00:00.007 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:00.007 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66634 Gb
0:00:00.007 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 1048576
0:00:00.133 2G / 2G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:00.178 16M / 2G INFO General (kmer_splitters.hpp : 308) Used 2034 reads
0:00:00.178 16M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:00.238 16M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 16947 kmers in total.
0:00:00.238 16M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:00.289 16M / 2G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:00.291 16M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:00.291 16M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 4 threads. This might take a while.
0:00:00.293 16M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 32768
0:00:00.293 16M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 1.66536 Gb
0:00:00.293 16M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144
0:00:00.755 3G / 3G INFO General (kmer_splitters.hpp : 380) Processed 16947 kmers
0:00:00.756 3G / 3G INFO General (kmer_splitters.hpp : 385) Used 16947 kmers.
0:00:00.758 16M / 3G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:00.971 16M / 3G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 17346 kmers in total.
0:00:00.972 16M / 3G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:01.068 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:01.085 16M / 3G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:00:01.128 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 17016 bytes occupied (7.8478 bits per kmer).
0:00:01.128 16M / 3G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:00:01.131 16M / 3G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:00:01.131 16M / 3G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:00:01.132 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:00:01.136 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 579 sequences extracted
0:00:01.138 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:00:01.139 16M / 3G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:00:01.140 16M / 3G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:00:01.140 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:01.140 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:00:01.146 16M / 3G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 10096 bytes occupied (4.76592 bits per kmer).
0:00:01.146 16M / 3G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:00:01.147 16M / 3G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:00:01.149 16M / 3G INFO General (construction.cpp : 464) Processed 1158 edges
0:00:01.153 16M / 3G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
=== Stack Trace ===
[0x5f9c52]
[0x58ada1]
[0x55d191]
[0x408c19]
[0x40123c]
[0x87b11b]
[0x407c01]
Verification of expression 'cov_.size() > 10' failed in function 'void coverage_model::KMerCoverageModel::Fit()'. In file '/spades/assembler/src/common/modules/coverage_model/kmer_coverage_model.cpp' on line 187. Message 'Invalid kmer coverage histogram, make sure that the coverage is indeed uniform'.
Verification of expression 'cov_.size() > 10' failed in function 'void coverage_model::KMerCoverageModel::Fit()'. In file '/spades/assembler/src/common/modules/coverage_model/kmer_coverage_model.cpp' on line 187. Message 'Invalid kmer coverage histogram, make sure that the coverage is indeed uniform'.
spades-core: /spades/assembler/src/common/modules/coverage_model/kmer_coverage_model.cpp:187: void coverage_model::KMerCoverageModel::Fit(): Assertion `cov_.size() > 10' failed.
== Error == system call for: "['/home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades-core', '/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/K127/configs/config.info']" finished abnormally, err code: -6
======= SPAdes pipeline finished abnormally and WITH WARNINGS!
=== Error correction and assembling warnings:
* 0:00:01.463 16M / 3G WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable
* 0:00:01.695 16M / 3G WARN General (kmer_coverage_model.cpp : 327) Valley value was estimated improperly, reset to 5
* 0:00:01.695 16M / 3G WARN General (kmer_coverage_model.cpp : 366) Failed to determine erroneous kmer threshold. Threshold set to: 5
* 0:00:03.698 16M / 3G WARN General (simplification.cpp : 479) The determined erroneous connection coverage threshold may be determined improperly
* 0:00:01.215 16M / 3G WARN General (kmer_coverage_model.cpp : 327) Valley value was estimated improperly, reset to 2
======= Warnings saved to /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/warnings.log
=== ERRORs:
* system call for: "['/home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades-core', '/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/pipeline/phyloflash/after_None/G1201/wol/bbmap/G1201.spades/K127/configs/config.info']" finished abnormally, err code: -6
In case you have troubles running SPAdes, you can write to [email protected]
or report an issue on our GitHub repository github.com/ablab/spades
Please provide us with params.txt and spades.log files from the output directory.
PS: I did not get the chance to run the latest 3.3b4 for my other issue. Stay tuned!
Yes unfortunately it is hard to predict what will happen because it very much depends on the library composition. Sometimes SPAdes works, sometimes Emirge works, sometimes neither (or both!), so it's good for a first screening but definitely you should dive in more deeply afterwards if necessary.
With the -poscov option you can run the extracted reads against a HMM of the 16S / 18S genes and see whether the coverage is very uneven in certain places. We implemented that after noticing that sometimes SSU amplicon libraries can contaminate a metagenome library if demultiplexing went wrong, and completely mess things up.
Great to hear - I was also thinking the possibility that 16S contaminants in a shotgun library would easily stacked up the to indigenous level, and necessarily skew coverage for one region. Thanks I'll be sure to tick this options too.
@kbseah about using the latest, v 3.3b4:
I did
wget https://github.com/HRGV/phyloFlash/archive/pf3.3b4.tar.gz
but the executable within says:
./phyloFlash.pl -version
This is phyloFlash v3.3b3
Is that only a typo? (just wanted to make sure before consuming CPU resources). Thanks
I've just re-run using this version (which I guess is 3.3b4) and it run to completion. It seems the HASH error is solved is the newer version (note: I did rebuild the custom database). Closing the issue! Thanks, Franck
Nope, the error persists. Hence I need to reopen.
Command is:
phyloFlash.pl \
-read1 /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G0055_R1.fastq.gz \
-read2 /panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G0055_R2.fastq.gz \
-readlength 150 \
-dbhome /home/flejzerowicz/softs/phyloflash/WOLBB \
-lib G0055 \
-CPUs 6 \
-clusterid 98 \
-taxlevel 7
Output is:
This is phyloFlash v3.3b3
[10:27:41] Using dbhome '/home/flejzerowicz/softs/phyloflash/WOLBB'
[10:27:41] working on library G0055
[10:27:41] Forward reads
/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G0055_R1.fastq.gz
[10:27:41] Reverse reads
/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G0055_R2.fastq.gz
[10:27:41] Current operating system linux
[10:27:41] Checking for required tools.
[10:27:41] Using reformat found at
"/home/flejzerowicz/softs/bbmap/reformat.sh".
[10:27:41] Using fastaFromBed found at "/opt/bedtools/2.26.0/fastaFromBed".
[10:27:41] Using sed found at
"/home/flejzerowicz/usr/miniconda3/envs/phyloflash/bin/sed".
[10:27:41] Using barrnap found at
"/home/flejzerowicz/softs/phyloflash/barrnap-HGV/bin/barrnap_HGV".
[10:27:41] Using grep found at "/bin/grep".
[10:27:41] Using cat found at "/bin/cat".
[10:27:41] Using nhmmer found at
"/home/flejzerowicz/softs/phyloflash/barrnap-HGV/binaries/linux/nhmmer".
[10:27:41] Using mafft found at "/home/flejzerowicz/softs/bin/mafft".
[10:27:41] Using vsearch found at
"/home/flejzerowicz/softs/vsearch-2.15.0-linux-x86_64/bin/vsearch".
[10:27:41] Using bbmap found at "/home/flejzerowicz/softs/bbmap/bbmap.sh".
[10:27:41] Using plotscript_SVG found at
"/home/flejzerowicz/softs/phyloflash/phyloFlash_plotscript_svg.pl".
[10:27:41] Using spades found at
"/home/flejzerowicz/softs/SPAdes-3.13.0-Linux/bin/spades.py".
[10:27:41] Using awk found at "/bin/awk".
[10:27:41] All required tools found.
[10:27:41] filtering reads with SSU db using minimum identity of 70%
[10:27:41] running subcommand:
/home/flejzerowicz/softs/bbmap/bbmap.sh fast=t minidentity=0.7
-Xmx20g reads=-1 threads=6 po=f outputunmapped=f
path=/home/flejzerowicz/softs/phyloflash/WOLBB
out=G0055.bbmap.sam outm=G0055.G0055_R1.fastq.gz.SSU.1.fq
noheader=t ambiguous=all build=1
in=/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G0055_R1.fastq.gz
bhist=G0055.basecompositionhistogram ihist=G0055.inserthistogram
idhist=G0055.idhistogram scafstats=G0055.hitstats overwrite=t
outm2=G0055.G0055_R1.fastq.gz.SSU.2.fq pairlen=1200
in2=/panfs/panfs1.ucsd.edu/panscratch/flejzerowicz/mv.cvrtr.pnfs/projects/fastqs/G0055_R2.fastq.gz
2>G0055.bbmap.out
[10:27:54] done...
[10:27:54] Reading SAM file G0055.bbmap.sam into memory
[10:27:54] Writing fixed SAM file to G0055.G0055_R1.fastq.gz.SSU.sam
[10:27:54] Done
[10:27:54] Total read segments processed: 1682728
[10:27:54] insert size median: 302
[10:27:54] insert size std deviation: 113
[10:27:54] Summarizing taxonomy from mapping hits to SILVA database
Can't use string ("2") as a HASH ref while "strict refs" in use at /home/flejzerowicz/softs/phyloflash/PhyloFlash.pm line 806.
Again, it says This is phyloFlash v3.3b3 but I believe this is a typo as I am using phyloFlash.pl from the 3.3b4 archive.
Attached, the file G0055.G0055_R1.fastq.gz.SSU.sam but not sure if I can attached the DB. Do you have a preferred way to share files?
Just as a possible parsing issue you may know of: may the taxonomies have characters such as [?, indeed I have this entry in the sam file:
A00953:38:HWHL5DSXX:2:1112:14968:12289 329 G000155855_1.1342952.1344472 k__Bacteria;p__Firmicutes;c__Clostridia;o__Clostridiales;f__;g__;s__[Bacteroides] pectinophilus 1383 3 37=1X12=1X4=1X10=1X14=1X57=12S = 1383 0 * * NM:i:5 AM:i:0 NH:i:3
G0055.G0055_R1.fastq.gz.SSU.sam.gz
Thanks!