Skip to content

Instantly share code, notes, and snippets.

@michaelbarton

michaelbarton/spades_log.txt

Created September 15, 2017 00:11
Show Gist options
  • Save michaelbarton/f4f55227ac3b31605b6edc47b393c92a to your computer and use it in GitHub Desktop.
Save michaelbarton/f4f55227ac3b31605b6edc47b393c92a to your computer and use it in GitHub Desktop.
Download ZIP
Spades log on unnormalised single cell data
Raw
spades_log.txt
+ TASK=merge
++ fetch_task_from_taskfile.sh /usr/local/share/Taskfile merge
+ CMD=' production_pipeline_merged_reads.sh ${READS} ${CONTIGS}'
++ biobox_args.sh 'select(has("fastq")) | .fastq | map(.value) | join(",")'
+ READS=/bbx/mount/n5ERGV8O49Zk88yXlx4Vk51Q4/661e5b3077313052c79383ea12f7e0a2aaea0e93ec405f9c96619038e981553d.fq.gz
+ CONTIGS=/bbx/output/contigs.fa
++ grep MemTotal: /proc/meminfo
++ tr -s ' '
++ cut -f 2 -d ' '
+ MEM_IN_KB=32946432
+ USAGE_PERCENT=85
+ let 'HEAP_IN_KB=32946432*85/100'
+ export _JAVA_OPTIONS=-Xmx28004467k
+ _JAVA_OPTIONS=-Xmx28004467k
+ eval production_pipeline_merged_reads.sh '${READS}' '${CONTIGS}'
++ production_pipeline_merged_reads.sh /bbx/mount/n5ERGV8O49Zk88yXlx4Vk51Q4/661e5b3077313052c79383ea12f7e0a2aaea0e93ec405f9c96619038e981553d.fq.gz /bbx/output/contigs.fa
+ SEQ_FILES=/usr/local/bbmap/resources
++ mktemp -d
+ TMP_READS_1=/tmp/tmp.NuCAMfqaNO/reads.fq.gz
++ mktemp -d
+ TMP_READS_2=/tmp/tmp.KT9cpaBXhe/reads.fq.gz
++ mktemp -d
+ TMP_OUT=/tmp/tmp.rzr9ZjS78c
++ mktemp -d
+ FILTERED_READS=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz
++ mktemp -d
+ OUTPUT_MERGED=/tmp/tmp.AzsDG8zqLS/merged.fq.gz
++ mktemp -d
+ OUTPUT_UNMERGED=/tmp/tmp.fyFUUmBILZ/unmerged.fq.gz
+ INPUT=/bbx/mount/n5ERGV8O49Zk88yXlx4Vk51Q4/661e5b3077313052c79383ea12f7e0a2aaea0e93ec405f9c96619038e981553d.fq.gz
+ OUTPUT=/bbx/output/contigs.fa
+ clumpify.sh interleaved=t pigz=t unpigz=t zl=4 passes=1 reorder in1=/bbx/mount/n5ERGV8O49Zk88yXlx4Vk51Q4/661e5b3077313052c79383ea12f7e0a2aaea0e93ec405f9c96619038e981553d.fq.gz out1=/tmp/tmp.NuCAMfqaNO/reads.fq.gz
Picked up _JAVA_OPTIONS: -Xmx28004467k
java version "1.7.0_151"
OpenJDK Runtime Environment (IcedTea 2.6.11) (7u151-2.6.11-1~deb8u1)
OpenJDK 64-Bit Server VM (build 24.151-b01, mixed mode)
java -ea -Xmx12197m -Xms12197m -cp /usr/local/bbmap/current/ clump.Clumpify interleaved=t pigz=t unpigz=t zl=4 passes=1 reorder in1=/bbx/mount/n5ERGV8O49Zk88yXlx4Vk51Q4/661e5b3077313052c79383ea12f7e0a2aaea0e93ec405f9c96619038e981553d.fq.gz out1=/tmp/tmp.NuCAMfqaNO/reads.fq.gz
Picked up _JAVA_OPTIONS: -Xmx28004467k
Executing clump.Clumpify [interleaved=t, pigz=t, unpigz=t, zl=4, passes=1, reorder, in1=/bbx/mount/n5ERGV8O49Zk88yXlx4Vk51Q4/661e5b3077313052c79383ea12f7e0a2aaea0e93ec405f9c96619038e981553d.fq.gz, out1=/tmp/tmp.NuCAMfqaNO/reads.fq.gz]
Clumpify version 37.50
Set INTERLEAVED to true
Read Estimate: 7535438
Memory Estimate: 4874 MB
Memory Available: 17469 MB
Set groups to 1
Executing clump.KmerSort [in1=/bbx/mount/n5ERGV8O49Zk88yXlx4Vk51Q4/661e5b3077313052c79383ea12f7e0a2aaea0e93ec405f9c96619038e981553d.fq.gz, in2=null, out1=/tmp/tmp.NuCAMfqaNO/reads.fq.gz, out2=null, groups=1, ecco=false, rename=false, shortname=f, unpair=false, repair=false, namesort=false, ow=true, pigz=t, unpigz=t, zl=4, passes=1, reorder]
Making comparator.
Made a comparator with k=31, seed=1, border=1, hashes=4
Starting cris 0.
Fetching reads.
Making fetch threads.
Starting threads.
Waiting for threads.
Fetch time: 10.388 seconds.
Closing input stream.
Combining thread output.
Combine time: 0.010 seconds.
Sorting.
Sort time: 6.407 seconds.
Making clumps.
Clump time: 0.666 seconds.
Writing.
Waiting for writing to complete.
Write time: 7.514 seconds.
Done!
Time: 25.231 seconds.
Reads Processed: 5000k 198.17k reads/sec
Bases Processed: 755m 29.92m bases/sec
Reads In: 5000000
Clumps Formed: 315790
Total time: 25.531 seconds.
+ bbduk.sh interleaved=t ktrim=r ordered minlen=51 minlenfraction=0.33 mink=11 tbo tpe rcomp=f overwrite=true k=23 hdist=1 hdist2=1 ftm=5 zl=4 ow=true rqc=hashmap loglog ref=/usr/local/bbmap/resources/adapters.fa in1=/tmp/tmp.NuCAMfqaNO/reads.fq.gz out1=stdout.fq
+ bbduk.sh interleaved=t ordered overwrite=true k=20 hdist=1 pigz=t zl=6 ow=true ref=/usr/local/bbmap/resources/short.fa in1=stdin.fq out1=/tmp/tmp.KT9cpaBXhe/reads.fq.gz
java -Djava.library.path=/usr/local/bbmap/jni/ -ea -Xmx6255m -Xms6255m -cp /usr/local/bbmap/current/ jgi.BBDukF interleaved=t ordered overwrite=true k=20 hdist=1 pigz=t zl=6 ow=true ref=/usr/local/bbmap/resources/short.fa in1=stdin.fq out1=/tmp/tmp.KT9cpaBXhe/reads.fq.gz
java -Djava.library.path=/usr/local/bbmap/jni/ -ea -Xmx6255m -Xms6255m -cp /usr/local/bbmap/current/ jgi.BBDukF interleaved=t ktrim=r ordered minlen=51 minlenfraction=0.33 mink=11 tbo tpe rcomp=f overwrite=true k=23 hdist=1 hdist2=1 ftm=5 zl=4 ow=true rqc=hashmap loglog ref=/usr/local/bbmap/resources/adapters.fa in1=/tmp/tmp.NuCAMfqaNO/reads.fq.gz out1=stdout.fq
Picked up _JAVA_OPTIONS: -Xmx28004467k
Picked up _JAVA_OPTIONS: -Xmx28004467k
Executing jgi.BBDukF [interleaved=t, ordered, overwrite=true, k=20, hdist=1, pigz=t, zl=6, ow=true, ref=/usr/local/bbmap/resources/short.fa, in1=stdin.fq, out1=/tmp/tmp.KT9cpaBXhe/reads.fq.gz]
BBDuk version 37.50
Executing jgi.BBDukF [interleaved=t, ktrim=r, ordered, minlen=51, minlenfraction=0.33, mink=11, tbo, tpe, rcomp=f, overwrite=true, k=23, hdist=1, hdist2=1, ftm=5, zl=4, ow=true, rqc=hashmap, loglog, ref=/usr/local/bbmap/resources/adapters.fa, in1=/tmp/tmp.NuCAMfqaNO/reads.fq.gz, out1=stdout.fq]
BBDuk version 37.50
Set INTERLEAVED to true
Set ORDERED to true
Set INTERLEAVED to true
Set ORDERED to true
maskMiddle was disabled because useShortKmers=true
Initial:
Memory: max=25491m, free=6154m, used=131m
Initial:
Memory: max=25491m, free=6154m, used=131m
Added 580 kmers; time: 0.040 seconds.
Memory: max=25491m, free=5924m, used=361m
Input is being processed as paired
Started output streams: 0.019 seconds.
Added 220612 kmers; time: 0.104 seconds.
Memory: max=25491m, free=5859m, used=426m
Input is being processed as paired
Started output streams: 0.011 seconds.
Processing time: 37.772 seconds.
Input: 5000000 reads 755000000 bases.
FTrimmed: 5000000 reads (100.00%) 5000000 bases (0.66%)
KTrimmed: 819628 reads (16.39%) 95698572 bases (12.68%)
Trimmed by overlap: 70778 reads (1.42%) 389974 bases (0.05%)
Total Removed: 581488 reads (11.63%) 101088546 bases (13.39%)
Result: 4418512 reads (88.37%) 653911454 bases (86.61%)
Unique 31-mers: 32360492
Time: 37.901 seconds.
Reads Processed: 5000k 131.92k reads/sec
Bases Processed: 755m 19.92m bases/sec
Processing time: 38.034 seconds.
Input: 4418512 reads 653911454 bases.
Contaminants: 522 reads (0.01%) 73404 bases (0.01%)
Total Removed: 522 reads (0.01%) 73404 bases (0.01%)
Result: 4417990 reads (99.99%) 653838050 bases (99.99%)
Time: 38.108 seconds.
Reads Processed: 4418k 115.95k reads/sec
Bases Processed: 653m 17.16m bases/sec
+ reformat.sh interleaved=t samplereadstarget=5000000 pigz=t unpigz=t in1=/tmp/tmp.KT9cpaBXhe/reads.fq.gz out1=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz
java -ea -Xmx200m -cp /usr/local/bbmap/current/ jgi.ReformatReads interleaved=t samplereadstarget=5000000 pigz=t unpigz=t in1=/tmp/tmp.KT9cpaBXhe/reads.fq.gz out1=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz
Picked up _JAVA_OPTIONS: -Xmx28004467k
Executing jgi.ReformatReads [interleaved=t, samplereadstarget=5000000, pigz=t, unpigz=t, in1=/tmp/tmp.KT9cpaBXhe/reads.fq.gz, out1=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz]
Set INTERLEAVED to true
Input is being processed as paired
Writing interleaved.
Input: 4417990 reads 653838050 bases
Output: 4417990 reads (100.00%) 653838050 bases (100.00%)
Time: 15.920 seconds.
Reads Processed: 4417k 277.50k reads/sec
Bases Processed: 653m 41.07m bases/sec
+ bbmerge-auto.sh interleaved=t in=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz out=/tmp/tmp.AzsDG8zqLS/merged.fq.gz outu=/tmp/tmp.fyFUUmBILZ/unmerged.fq.gz pigz=t strict k=93 extend2=80 rem ordered
java -Djava.library.path=/usr/local/bbmap/jni/ -ea -Xmx12521m -Xms12521m -cp /usr/local/bbmap/current/ jgi.BBMerge interleaved=t in=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz out=/tmp/tmp.AzsDG8zqLS/merged.fq.gz outu=/tmp/tmp.fyFUUmBILZ/unmerged.fq.gz pigz=t strict k=93 extend2=80 rem ordered
Picked up _JAVA_OPTIONS: -Xmx28004467k
Executing jgi.BBMerge [interleaved=t, in=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz, out=/tmp/tmp.AzsDG8zqLS/merged.fq.gz, outu=/tmp/tmp.fyFUUmBILZ/unmerged.fq.gz, pigz=t, strict, k=93, extend2=80, rem, ordered]
BBMerge version 37.50
Revised arguments: [maxbad=4, margin=3, minqo=8, qualiters=2, ratiomode=t, flatmode=f, minentropy=42, minoverlap0=7, minoverlap=11, maxratio=0.075, ratiomargin=7.5, ratiooffset=0.55, ratiominoverlapreduction=4, efilter=4, pfilter=0.0008, minsecondratio=0.12, minapproxoverlap=24, interleaved=t, in=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz, out=/tmp/tmp.AzsDG8zqLS/merged.fq.gz, outu=/tmp/tmp.fyFUUmBILZ/unmerged.fq.gz, pigz=t, k=93, extend2=80, rem, ordered]
Set INTERLEAVED to true
Executing assemble.Tadpole2 [in=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz, branchlower=3, branchmult1=20.0, branchmult2=3.0, mincountseed=3, mincountextend=2, minprob=0.5, k=93, prealloc=false, prefilter=0, ecctail=false, eccpincer=false, eccreassemble=true]
Tadpole version 37.50
Using 8 threads.
Executing ukmer.KmerTableSetU [in=/tmp/tmp.GlqWKqa5Eo/reads.fq.gz, branchlower=3, branchmult1=20.0, branchmult2=3.0, mincountseed=3, mincountextend=2, minprob=0.5, k=93, prealloc=false, prefilter=0, ecctail=false, eccpincer=false, eccreassemble=true]
Initial:
Ways=31, initialSize=128000, prefilter=f, prealloc=f
Memory: max=25491m, free=12451m, used=131m
Estimated kmer capacity: 315833034
After table allocation:
Memory: max=25491m, free=12320m, used=262m
After loading:
Memory: max=25491m, free=11096m, used=1486m
Input: 4417990 reads 653838050 bases.
Unique Kmers: 7876699
Load Time: 13.839 seconds.
Writing mergable reads merged.
Started output threads.
Total time: 80.497 seconds.
Pairs: 2208995
Joined: 1442915 65.320%
Ambiguous: 759422 34.379%
No Solution: 6658 0.301%
Too Short: 0 0.000%
Fully Extended: 2813218 63.676%
Partly Extended: 625221 14.152%
Not Extended: 979551 22.172%
Avg Insert: 257.3
Standard Deviation: 84.0
Mode: 237
Insert range: 35 - 451
90th percentile: 373
75th percentile: 319
50th percentile: 253
25th percentile: 193
10th percentile: 149
+ ARGS=()
+ [[ ! -s /tmp/tmp.fyFUUmBILZ/unmerged.fq.gz ]]
+ ARGS+=(" --pe1-12 ${OUTPUT_UNMERGED}")
+ [[ ! -s /tmp/tmp.AzsDG8zqLS/merged.fq.gz ]]
+ ARGS+=(" --s2 ${OUTPUT_MERGED}")
++ nproc
+ spades.py --pe1-12 /tmp/tmp.fyFUUmBILZ/unmerged.fq.gz --s2 /tmp/tmp.AzsDG8zqLS/merged.fq.gz -o /tmp/tmp.rzr9ZjS78c --threads 8 --phred-offset 33 --cov-cutoff auto --careful -k 25,55,95
Command line: /usr/local/bin/spades.py --pe1-12 /tmp/tmp.fyFUUmBILZ/unmerged.fq.gz --s2 /tmp/tmp.AzsDG8zqLS/merged.fq.gz -o /tmp/tmp.rzr9ZjS78c --threads 8 --phred-offset 33 --cov-cutoff auto --careful -k 25,55,95
System information:
SPAdes version: 3.11.0
Python version: 2.7.9
OS: Linux-4.4.0-31-generic-x86_64-with-debian-8.8
Output dir: /tmp/tmp.rzr9ZjS78c
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: not specified
right reads: not specified
interlaced reads: ['/tmp/tmp.fyFUUmBILZ/unmerged.fq.gz']
single reads: not specified
Library number: 2, library type: single
left reads: not specified
right reads: not specified
interlaced reads: not specified
single reads: ['/tmp/tmp.AzsDG8zqLS/merged.fq.gz']
Read error correction parameters:
Iterations: 1
PHRED offset: 33
Corrected reads will be compressed (with gzip)
Assembly parameters:
k: [25, 55, 95]
Repeat resolution is enabled
Mismatch careful mode is turned ON
MismatchCorrector will be used
Coverage cutoff is turned ON and threshold will be auto-detected
Other parameters:
Dir for temp files: /tmp/tmp.rzr9ZjS78c/tmp
Threads: 8
Memory limit (in Gb): 31
======= SPAdes pipeline started. Log can be found here: /tmp/tmp.rzr9ZjS78c/spades.log
== Splitting /tmp/tmp.fyFUUmBILZ/unmerged.fq.gz into left and right reads (in /tmp/tmp.rzr9ZjS78c/split_input directory)
===== Read error correction started.
== Running read error correction tool: /usr/local/spades/bin/hammer /tmp/tmp.rzr9ZjS78c/corrected/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 83) Starting BayesHammer, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 84) Loading config from /tmp/tmp.rzr9ZjS78c/corrected/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.hpp : 51) Memory limit set to 31 Gb
0:00:00.000 4M / 4M INFO General (hammer_tools.cpp : 36) Hamming graph threshold tau=1, k=21, subkmer positions = [ 0 10 ]
0:00:00.000 4M / 4M INFO General (main.cpp : 120) Size of aux. kmer data 24 bytes
=== ITERATION 0 begins ===
0:00:00.000 4M / 4M INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:00:00.000 4M / 4M INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:00:00.000 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:00.000 4M / 4M INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.2915 Gb
0:00:00.000 4M / 4M INFO General (kmer_splitters.hpp : 82) Using cell size of 524288
0:00:00.001 8G / 8G INFO K-mer Splitting (kmer_data.cpp : 96) Processing /tmp/tmp.rzr9ZjS78c/split_input/unmerged_1.fastq
0:00:05.529 8G / 8G INFO K-mer Splitting (kmer_data.cpp : 106) Processed 766080 reads
0:00:05.529 8G / 8G INFO K-mer Splitting (kmer_data.cpp : 96) Processing /tmp/tmp.rzr9ZjS78c/split_input/unmerged_2.fastq
0:00:11.330 8G / 8G INFO K-mer Splitting (kmer_data.cpp : 106) Processed 1532160 reads
0:00:11.330 8G / 8G INFO K-mer Splitting (kmer_data.cpp : 96) Processing /tmp/tmp.AzsDG8zqLS/merged.fq.gz
0:00:19.949 8G / 8G INFO K-mer Splitting (kmer_data.cpp : 106) Processed 2300939 reads
0:00:27.946 8G / 8G INFO K-mer Splitting (kmer_data.cpp : 106) Processed 2975075 reads
0:00:27.946 8G / 8G INFO K-mer Splitting (kmer_data.cpp : 111) Total 2975075 reads processed
0:00:27.958 32M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:28.632 32M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 39767550 kmers in total.
0:00:28.632 32M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:28.864 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:00:30.598 32M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:00:32.358 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 18448304 bytes occupied (3.71123 bits per kmer).
0:00:32.358 32M / 8G INFO K-mer Counting (kmer_data.cpp : 357) Arranging kmers in hash map order
0:00:34.325 640M / 8G INFO General (main.cpp : 155) Clustering Hamming graph.
0:01:26.796 640M / 8G INFO General (main.cpp : 162) Extracting clusters
0:01:33.655 640M / 8G INFO General (main.cpp : 174) Clustering done. Total clusters: 17072324
0:01:33.655 336M / 8G INFO K-mer Counting (kmer_data.cpp : 379) Collecting K-mer information, this takes a while.
0:01:33.963 1G / 8G INFO K-mer Counting (kmer_data.cpp : 385) Processing /tmp/tmp.rzr9ZjS78c/split_input/unmerged_1.fastq
0:01:53.625 1G / 8G INFO K-mer Counting (kmer_data.cpp : 385) Processing /tmp/tmp.rzr9ZjS78c/split_input/unmerged_2.fastq
0:02:13.662 1G / 8G INFO K-mer Counting (kmer_data.cpp : 385) Processing /tmp/tmp.AzsDG8zqLS/merged.fq.gz
0:03:19.138 1G / 8G INFO K-mer Counting (kmer_data.cpp : 392) Collection done, postprocessing.
0:03:19.272 1G / 8G INFO K-mer Counting (kmer_data.cpp : 406) There are 39767550 kmers in total. Among them 32319914 (81.2721%) are singletons.
0:03:19.272 1G / 8G INFO General (main.cpp : 180) Subclustering Hamming graph
0:08:46.376 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 649) Subclustering done. Total 649 non-read kmers were generated.
0:08:46.376 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 650) Subclustering statistics:
0:08:46.377 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 651) Total singleton hamming clusters: 16267342. Among them 540104 (3.32017%) are good
0:08:46.377 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 652) Total singleton subclusters: 4822. Among them 4682 (97.0966%) are good
0:08:46.377 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 653) Total non-singleton subcluster centers: 1551265. Among them 976143 (62.9256%) are good
0:08:46.377 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 654) Average size of non-trivial subcluster: 15.1514 kmers
0:08:46.377 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 655) Average number of sub-clusters per non-singleton cluster: 1.93307
0:08:46.377 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 656) Total solid k-mers: 1520929
0:08:46.377 1G / 8G INFO Hamming Subclustering (kmer_cluster.cpp : 657) Substitution probabilities: [4,4]((0.90027,0.029081,0.0198035,0.0508458),(0.0392121,0.928796,0.0196528,0.0123393),(0.011743,0.0192449,0.92906,0.0399523),(0.0500257,0.0193337,0.0283714,0.902269))
0:08:46.397 1G / 8G INFO General (main.cpp : 185) Finished clustering.
0:08:46.397 1G / 8G INFO General (main.cpp : 204) Starting solid k-mers expansion in 8 threads.
0:09:04.812 1G / 8G INFO General (main.cpp : 225) Solid k-mers iteration 0 produced 1846631 new k-mers.
0:09:23.213 1G / 8G INFO General (main.cpp : 225) Solid k-mers iteration 1 produced 378767 new k-mers.
0:09:41.580 1G / 8G INFO General (main.cpp : 225) Solid k-mers iteration 2 produced 45145 new k-mers.
0:09:59.952 1G / 8G INFO General (main.cpp : 225) Solid k-mers iteration 3 produced 5847 new k-mers.
0:10:18.329 1G / 8G INFO General (main.cpp : 225) Solid k-mers iteration 4 produced 532 new k-mers.
0:10:36.685 1G / 8G INFO General (main.cpp : 225) Solid k-mers iteration 5 produced 79 new k-mers.
0:10:55.039 1G / 8G INFO General (main.cpp : 225) Solid k-mers iteration 6 produced 0 new k-mers.
0:10:55.040 1G / 8G INFO General (main.cpp : 229) Solid k-mers finalized
0:10:55.040 1G / 8G INFO General (hammer_tools.cpp : 211) Starting read correction in 8 threads.
0:10:55.040 1G / 8G INFO General (hammer_tools.cpp : 222) Correcting pair of reads: /tmp/tmp.rzr9ZjS78c/split_input/unmerged_1.fastq and /tmp/tmp.rzr9ZjS78c/split_input/unmerged_2.fastq
0:10:57.179 1G / 8G INFO General (hammer_tools.cpp : 166) Prepared batch 0 of 766080 reads.
0:14:45.726 2G / 8G INFO General (hammer_tools.cpp : 175) Processed batch 0
0:14:47.234 2G / 8G INFO General (hammer_tools.cpp : 185) Written batch 0
0:14:47.746 1G / 8G INFO General (hammer_tools.cpp : 249) Correcting single reads: /tmp/tmp.AzsDG8zqLS/merged.fq.gz
0:14:51.098 1G / 8G INFO General (hammer_tools.cpp : 125) Prepared batch 0 of 800000 reads.
0:14:56.653 1G / 8G INFO General (hammer_tools.cpp : 131) Processed batch 0
0:14:57.757 1G / 8G INFO General (hammer_tools.cpp : 135) Written batch 0
0:15:00.454 2G / 8G INFO General (hammer_tools.cpp : 125) Prepared batch 1 of 642915 reads.
0:15:06.896 2G / 8G INFO General (hammer_tools.cpp : 131) Processed batch 1
0:15:07.815 2G / 8G INFO General (hammer_tools.cpp : 135) Written batch 1
0:15:08.179 1G / 8G INFO General (hammer_tools.cpp : 270) Correction done. Changed 1589854 bases in 426977 reads.
0:15:08.179 1G / 8G INFO General (hammer_tools.cpp : 271) Failed to correct 156738 bases out of 600376990.
0:15:08.183 32M / 8G INFO General (main.cpp : 262) Saving corrected dataset description to /tmp/tmp.rzr9ZjS78c/corrected/corrected.yaml
0:15:08.183 32M / 8G INFO General (main.cpp : 269) All done. Exiting.
== Compressing corrected reads (with gzip)
== Dataset description file was created: /tmp/tmp.rzr9ZjS78c/corrected/corrected.yaml
===== Read error correction finished.
===== Assembling started.
== Running assembler: K25
0:00:00.000 4M / 4M INFO General (main.cpp : 76) Loading config from /tmp/tmp.rzr9ZjS78c/K25/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 76) Loading config from /tmp/tmp.rzr9ZjS78c/K25/configs/careful_mode.info
0:00:00.000 4M / 4M INFO General (memory_limit.hpp : 51) Memory limit set to 31 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 91) Assembling dataset (/tmp/tmp.rzr9ZjS78c/dataset.info) with K=25
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 : 61) Two-step RR enabled: 0
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 126) STAGE == Construction
0:00:00.000 4M / 4M INFO General (read_converter.hpp : 84) Converting reads to binary format for library #0 (takes a while)
0:00:00.000 4M / 4M INFO General (read_converter.hpp : 85) Converting paired reads
0:00:00.154 80M / 80M INFO General (binary_converter.hpp : 139) 16384 reads processed
0:00:00.274 96M / 96M INFO General (binary_converter.hpp : 139) 32768 reads processed
0:00:00.514 128M / 128M INFO General (binary_converter.hpp : 139) 65536 reads processed
0:00:00.995 188M / 188M INFO General (binary_converter.hpp : 139) 131072 reads processed
0:00:01.957 312M / 312M INFO General (binary_converter.hpp : 139) 262144 reads processed
0:00:03.886 552M / 552M INFO General (binary_converter.hpp : 139) 524288 reads processed
0:00:06.414 760M / 760M INFO General (binary_converter.hpp : 159) 748859 reads written
0:00:07.067 4M / 760M INFO General (read_converter.hpp : 94) Converting single reads
0:00:07.223 136M / 760M INFO General (binary_converter.hpp : 159) 11345 reads written
0:00:07.228 4M / 760M INFO General (read_converter.hpp : 84) Converting reads to binary format for library #1 (takes a while)
0:00:07.228 4M / 760M INFO General (read_converter.hpp : 85) Converting paired reads
0:00:07.275 68M / 760M INFO General (binary_converter.hpp : 159) 0 reads written
0:00:07.275 4M / 760M INFO General (read_converter.hpp : 94) Converting single reads
0:00:07.432 144M / 760M INFO General (binary_converter.hpp : 139) 16384 reads processed
0:00:07.515 152M / 760M INFO General (binary_converter.hpp : 139) 32768 reads processed
0:00:07.682 176M / 760M INFO General (binary_converter.hpp : 139) 65536 reads processed
0:00:08.014 224M / 760M INFO General (binary_converter.hpp : 139) 131072 reads processed
0:00:08.675 316M / 760M INFO General (binary_converter.hpp : 139) 262144 reads processed
0:00:09.991 496M / 760M INFO General (binary_converter.hpp : 139) 524288 reads processed
0:00:12.616 864M / 864M INFO General (binary_converter.hpp : 139) 1048576 reads processed
0:00:15.476 1G / 1G INFO General (binary_converter.hpp : 159) 1442914 reads written
0:00:16.151 4M / 1G INFO General (graph_construction.hpp : 120) Constructing DeBruijn graph for k=25
0:00:16.151 4M / 1G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 64 buckets using 8 threads. This might take a while.
0:00:16.151 4M / 1G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:16.151 4M / 1G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.2915 Gb
0:00:16.151 4M / 1G INFO General (kmer_splitters.hpp : 82) Using cell size of 1048576
0:00:27.375 6G / 6G INFO General (kmer_splitters.hpp : 291) Processed 5405239 reads
0:00:28.724 6G / 6G INFO General (kmer_splitters.hpp : 291) Processed 5903954 reads
0:00:28.725 6G / 6G INFO General (kmer_splitters.hpp : 297) Adding contigs from previous K
0:00:28.738 32M / 6G INFO General (kmer_splitters.hpp : 310) Used 5903954 reads. Maximum read length 451
0:00:28.738 32M / 6G INFO General (kmer_splitters.hpp : 311) Average read length 202.172
0:00:28.738 32M / 6G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:28.864 32M / 6G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 9400522 kmers in total.
0:00:28.864 32M / 6G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:28.921 32M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:00:28.921 32M / 6G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:00:28.921 32M / 6G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:28.921 32M / 6G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.29036 Gb
0:00:28.921 32M / 6G INFO General (kmer_splitters.hpp : 82) Using cell size of 524288
0:00:29.905 8G / 8G INFO General (kmer_splitters.hpp : 381) Processed 9400522 kmers
0:00:29.906 8G / 8G INFO General (kmer_splitters.hpp : 386) Used 9400522 kmers.
0:00:29.916 32M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:30.029 32M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 8950806 kmers in total.
0:00:30.029 32M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:30.085 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:00:30.518 32M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:00:30.793 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 4158760 bytes occupied (3.71699 bits per kmer).
0:00:30.798 44M / 8G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 87) Building k-mer extensions from k+1-mers
0:00:31.474 44M / 8G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 91) Building k-mer extensions from k+1-mers finished.
0:00:31.474 44M / 8G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping
0:00:33.254 44M / 8G INFO Early tip clipping (early_simplification.hpp : 184) 3091496 26-mers were removed by early tip clipper
0:00:33.254 44M / 8G INFO General (graph_construction.hpp : 136) Condensing graph
0:00:33.265 44M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:00:34.283 88M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1107818 sequences extracted
0:00:34.817 88M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:00:35.085 88M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 5 loops collected
0:00:35.593 328M / 8G INFO General (graph_construction.hpp : 141) Building index with from graph
0:00:35.593 328M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:00:35.593 328M / 8G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:00:35.593 328M / 8G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:35.593 328M / 8G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.27832 Gb
0:00:35.593 328M / 8G INFO General (kmer_splitters.hpp : 82) Using cell size of 524288
0:00:36.080 8G / 8G INFO General (edge_index_builders.hpp : 75) Processed 2215608 edges
0:00:36.081 8G / 8G INFO General (edge_index_builders.hpp : 80) Used 2215608 sequences.
0:00:36.088 328M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:36.171 328M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 6309026 kmers in total.
0:00:36.172 328M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:36.212 328M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:00:36.486 332M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:00:36.761 332M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 2933880 bytes occupied (3.72023 bits per kmer).
0:00:36.810 480M / 8G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from graph, this takes a while.
0:00:37.249 480M / 8G INFO General (edge_index.hpp : 91) Index refilled
0:00:37.271 464M / 8G INFO General (graph_construction.hpp : 173) Filling coverage index
0:00:37.271 464M / 8G INFO General (edge_index_builders.hpp : 183) Collecting k-mer coverage information from reads, this takes a while.
0:01:10.965 464M / 8G INFO General (graph_construction.hpp : 175) Filling coverage and flanking coverage from index
0:01:11.499 464M / 8G INFO General (construction.cpp : 30) Figured out: read length = 451
0:01:11.499 464M / 8G INFO StageManager (stage.cpp : 126) STAGE == EC Threshold Finding
0:01:11.733 464M / 8G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 76
0:01:11.733 464M / 8G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 78
0:01:11.733 464M / 8G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 79. Coverage mad: 2.9652
0:01:11.733 464M / 8G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:11.944 464M / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:12.463 464M / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:14.384 464M / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:18.446 464M / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:26.282 464M / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 32
0:01:39.507 464M / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 64
0:01:39.507 464M / 8G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 33.7515. Fitted coverage std. dev: 14.6258
0:01:39.507 464M / 8G WARN General (kmer_coverage_model.cpp : 327) Valley value was estimated improperly, reset to 20
0:01:39.511 464M / 8G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.754678
0:01:39.511 464M / 8G WARN General (kmer_coverage_model.cpp : 366) Failed to determine erroneous kmer threshold. Threshold set to: 20
0:01:39.511 464M / 8G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 646148
0:01:39.511 464M / 8G INFO General (genomic_info_filler.cpp : 129) Failed to estimate mean coverage
0:01:39.512 464M / 8G INFO General (genomic_info_filler.cpp : 141) EC coverage threshold value was calculated as 20
0:01:39.512 464M / 8G INFO General (genomic_info_filler.cpp : 142) Trusted kmer low bound: 0
0:01:39.512 464M / 8G INFO StageManager (stage.cpp : 126) STAGE == Simplification
0:01:39.513 312M / 8G INFO General (simplification.cpp : 387) Graph simplification started
0:01:39.513 312M / 8G INFO General (simplification.cpp : 77) PROCEDURE == InitialCleaning
0:01:39.513 312M / 8G INFO General (graph_simplification.hpp : 645) Flanking coverage based disconnection disabled
0:01:39.513 312M / 8G INFO General (simplification.cpp : 356) Running Self conjugate edge remover
0:01:39.602 312M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:01:39.603 312M / 8G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
0:01:39.603 312M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 1
0:01:39.603 312M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:01:39.767 312M / 8G INFO General (simplification.cpp : 358) Triggered 5974 times
0:01:39.767 312M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:01:55.759 340M / 8G INFO General (simplification.cpp : 358) Triggered 8996 times
0:01:55.759 340M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:02.372 348M / 8G INFO General (simplification.cpp : 358) Triggered 278124 times
0:02:02.372 348M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 2
0:02:02.372 348M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:02.530 348M / 8G INFO General (simplification.cpp : 358) Triggered 3730 times
0:02:02.530 348M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:06.968 348M / 8G INFO General (simplification.cpp : 358) Triggered 7453 times
0:02:06.968 348M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:08.437 344M / 8G INFO General (simplification.cpp : 358) Triggered 67347 times
0:02:08.437 344M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 3
0:02:08.437 344M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:08.473 344M / 8G INFO General (simplification.cpp : 358) Triggered 82 times
0:02:08.473 344M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:11.249 344M / 8G INFO General (simplification.cpp : 358) Triggered 5717 times
0:02:11.249 344M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:11.869 344M / 8G INFO General (simplification.cpp : 358) Triggered 27725 times
0:02:11.869 344M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 4
0:02:11.869 344M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:11.887 344M / 8G INFO General (simplification.cpp : 358) Triggered 24 times
0:02:11.887 344M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:13.350 344M / 8G INFO General (simplification.cpp : 358) Triggered 3771 times
0:02:13.350 344M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:13.692 336M / 8G INFO General (simplification.cpp : 358) Triggered 14078 times
0:02:13.692 336M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 5
0:02:13.692 336M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:13.703 336M / 8G INFO General (simplification.cpp : 358) Triggered 6 times
0:02:13.703 336M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:14.765 336M / 8G INFO General (simplification.cpp : 358) Triggered 2540 times
0:02:14.765 336M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:14.977 316M / 8G INFO General (simplification.cpp : 358) Triggered 8163 times
0:02:14.977 316M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 6
0:02:14.977 316M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:14.985 316M / 8G INFO General (simplification.cpp : 358) Triggered 8 times
0:02:14.985 316M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:15.697 316M / 8G INFO General (simplification.cpp : 358) Triggered 1766 times
0:02:15.697 316M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:15.834 304M / 8G INFO General (simplification.cpp : 358) Triggered 5105 times
0:02:15.834 304M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 7
0:02:15.834 304M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:15.839 304M / 8G INFO General (simplification.cpp : 358) Triggered 5 times
0:02:15.839 304M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:16.302 304M / 8G INFO General (simplification.cpp : 358) Triggered 1347 times
0:02:16.302 304M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:16.395 284M / 8G INFO General (simplification.cpp : 358) Triggered 3375 times
0:02:16.395 284M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 8
0:02:16.395 284M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:16.399 280M / 8G INFO General (simplification.cpp : 358) Triggered 4 times
0:02:16.399 280M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:16.723 280M / 8G INFO General (simplification.cpp : 358) Triggered 1057 times
0:02:16.723 280M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:16.794 272M / 8G INFO General (simplification.cpp : 358) Triggered 2408 times
0:02:16.794 272M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 9
0:02:16.794 272M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:16.798 268M / 8G INFO General (simplification.cpp : 358) Triggered 6 times
0:02:16.798 268M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:17.016 268M / 8G INFO General (simplification.cpp : 358) Triggered 800 times
0:02:17.016 268M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:17.071 248M / 8G INFO General (simplification.cpp : 358) Triggered 1761 times
0:02:17.071 248M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 10
0:02:17.071 248M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:17.078 244M / 8G INFO General (simplification.cpp : 358) Triggered 28 times
0:02:17.078 244M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:17.326 244M / 8G INFO General (simplification.cpp : 358) Triggered 697 times
0:02:17.326 244M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:17.380 216M / 8G INFO General (simplification.cpp : 358) Triggered 1302 times
0:02:17.380 216M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 11
0:02:17.380 216M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:17.385 212M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.385 212M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:17.491 212M / 8G INFO General (simplification.cpp : 358) Triggered 509 times
0:02:17.491 212M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:17.491 212M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.491 212M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 12
0:02:17.491 212M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:17.491 208M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.491 208M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:17.491 208M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.491 208M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:17.491 208M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.491 208M / 8G INFO General (simplification.cpp : 167) PROCEDURE == Post simplification
0:02:17.491 208M / 8G INFO General (graph_simplification.hpp : 447) Disconnection of relatively low covered edges disabled
0:02:17.491 208M / 8G INFO General (graph_simplification.hpp : 477) Complex tip clipping disabled
0:02:17.492 208M / 8G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
0:02:17.492 208M / 8G INFO General (simplification.cpp : 301) Iteration 1
0:02:17.492 208M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:17.494 212M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.494 212M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:17.574 208M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.574 208M / 8G INFO General (simplification.cpp : 301) Iteration 2
0:02:17.574 208M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:17.577 212M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.577 212M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:17.656 208M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:17.656 208M / 8G INFO General (simplification.cpp : 333) Disrupting self-conjugate edges
0:02:17.672 208M / 8G INFO StageManager (stage.cpp : 126) STAGE == Simplification Cleanup
0:02:17.672 208M / 8G INFO General (simplification.cpp : 547) Removing isolated edges
0:02:17.688 196M / 8G INFO General (simplification.cpp : 570) Counting average coverage
0:02:17.693 196M / 8G INFO General (simplification.cpp : 575) Average coverage = 1251.71
0:02:17.693 196M / 8G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
0:02:17.693 196M / 8G INFO General (contig_output_stage.cpp : 40) Writing GFA to /tmp/tmp.rzr9ZjS78c//K25/assembly_graph_with_scaffolds.gfa
0:02:17.745 192M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K25/before_rr.fasta
0:02:17.817 192M / 8G INFO General (contig_output_stage.cpp : 50) Outputting FastG graph to /tmp/tmp.rzr9ZjS78c//K25/assembly_graph.fastg
0:02:18.043 192M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K25/simplified_contigs.fasta
0:02:18.119 192M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K25/final_contigs.fasta
0:02:18.195 192M / 8G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
0:02:18.195 192M / 8G INFO General (contig_output_stage.cpp : 40) Writing GFA to /tmp/tmp.rzr9ZjS78c//K25/assembly_graph_with_scaffolds.gfa
0:02:18.250 192M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K25/before_rr.fasta
0:02:18.323 192M / 8G INFO General (contig_output_stage.cpp : 50) Outputting FastG graph to /tmp/tmp.rzr9ZjS78c//K25/assembly_graph.fastg
0:02:18.551 192M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K25/simplified_contigs.fasta
0:02:18.628 192M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K25/final_contigs.fasta
0:02:18.704 192M / 8G INFO General (launch.hpp : 137) SPAdes finished
0:02:18.869 32M / 8G INFO General (main.cpp : 110) Assembling time: 0 hours 2 minutes 18 seconds
== Running assembler: K55
0:00:00.000 4M / 4M INFO General (main.cpp : 76) Loading config from /tmp/tmp.rzr9ZjS78c/K55/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 76) Loading config from /tmp/tmp.rzr9ZjS78c/K55/configs/careful_mode.info
0:00:00.000 4M / 4M INFO General (memory_limit.hpp : 51) Memory limit set to 31 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 91) Assembling dataset (/tmp/tmp.rzr9ZjS78c/dataset.info) with K=55
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 : 61) Two-step RR enabled: 0
0:00:00.000 4M / 4M INFO General (launch.hpp : 79) Will need read mapping, kmer mapper will be attached
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 126) STAGE == Construction
0:00:00.000 4M / 4M INFO General (read_converter.hpp : 67) Binary reads detected
0:00:00.000 4M / 4M INFO General (read_converter.hpp : 67) Binary reads detected
0:00:00.000 4M / 4M INFO General (graph_construction.hpp : 120) Constructing DeBruijn graph for k=55
0:00:00.000 4M / 4M INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 64 buckets using 8 threads. This might take a while.
0:00:00.000 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:00.000 4M / 4M INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.2915 Gb
0:00:00.000 4M / 4M INFO General (kmer_splitters.hpp : 82) Using cell size of 524288
0:00:07.196 6G / 6G INFO General (kmer_splitters.hpp : 291) Processed 3907726 reads
0:00:12.411 6G / 6G INFO General (kmer_splitters.hpp : 291) Processed 5903954 reads
0:00:12.411 6G / 6G INFO General (kmer_splitters.hpp : 297) Adding contigs from previous K
0:00:12.490 32M / 6G INFO General (kmer_splitters.hpp : 310) Used 5903954 reads. Maximum read length 451
0:00:12.490 32M / 6G INFO General (kmer_splitters.hpp : 311) Average read length 202.172
0:00:12.490 32M / 6G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:12.911 32M / 6G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 24950215 kmers in total.
0:00:12.911 32M / 6G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:13.204 32M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:00:13.204 32M / 6G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:00:13.204 32M / 6G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:13.204 32M / 6G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.29036 Gb
0:00:13.204 32M / 6G INFO General (kmer_splitters.hpp : 82) Using cell size of 262144
0:00:16.072 8G / 8G INFO General (kmer_splitters.hpp : 381) Processed 24950215 kmers
0:00:16.073 8G / 8G INFO General (kmer_splitters.hpp : 386) Used 24950215 kmers.
0:00:16.094 32M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:16.439 32M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 24581662 kmers in total.
0:00:16.440 32M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:16.723 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:00:17.876 32M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:00:20.347 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 11406632 bytes occupied (3.71224 bits per kmer).
0:00:20.361 56M / 8G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 87) Building k-mer extensions from k+1-mers
0:00:22.422 56M / 8G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 91) Building k-mer extensions from k+1-mers finished.
0:00:22.422 56M / 8G INFO General (graph_construction.hpp : 136) Condensing graph
0:00:22.454 56M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:00:25.947 180M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1866199 sequences extracted
0:00:28.003 180M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:00:28.731 180M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:00:29.746 620M / 8G INFO General (graph_construction.hpp : 141) Building index with from graph
0:00:29.746 620M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:00:29.746 620M / 8G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:00:29.746 620M / 8G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:29.746 620M / 8G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.26644 Gb
0:00:29.746 620M / 8G INFO General (kmer_splitters.hpp : 82) Using cell size of 262144
0:00:31.258 8G / 8G INFO General (edge_index_builders.hpp : 75) Processed 3732397 edges
0:00:31.258 8G / 8G INFO General (edge_index_builders.hpp : 80) Used 3732397 sequences.
0:00:31.266 620M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:31.616 620M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 24950215 kmers in total.
0:00:31.616 620M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:31.903 620M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:00:32.915 620M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:00:35.456 620M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 11577568 bytes occupied (3.71221 bits per kmer).
0:00:35.648 1G / 8G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from graph, this takes a while.
0:00:37.134 1G / 8G INFO General (edge_index.hpp : 91) Index refilled
0:00:37.245 1G / 8G INFO General (graph_construction.hpp : 173) Filling coverage index
0:00:37.245 1G / 8G INFO General (edge_index_builders.hpp : 183) Collecting k-mer coverage information from reads, this takes a while.
0:01:18.995 1G / 8G INFO General (graph_construction.hpp : 175) Filling coverage and flanking coverage from index
0:01:20.556 1G / 8G INFO General (construction.cpp : 30) Figured out: read length = 451
0:01:20.556 1G / 8G INFO StageManager (stage.cpp : 126) STAGE == EC Threshold Finding
0:01:20.947 1G / 8G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 67
0:01:20.947 1G / 8G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 69
0:01:20.947 1G / 8G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 70. Coverage mad: 2.9652
0:01:20.947 1G / 8G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:21.123 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:21.600 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:23.076 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:26.848 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:33.103 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 32
0:01:43.131 1G / 8G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 28.9321. Fitted coverage std. dev: 10.5258
0:01:43.131 1G / 8G WARN General (kmer_coverage_model.cpp : 327) Valley value was estimated improperly, reset to 7
0:01:43.133 1G / 8G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1
0:01:43.133 1G / 8G WARN General (kmer_coverage_model.cpp : 366) Failed to determine erroneous kmer threshold. Threshold set to: 7
0:01:43.133 1G / 8G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 1501467
0:01:43.133 1G / 8G INFO General (genomic_info_filler.cpp : 129) Failed to estimate mean coverage
0:01:43.134 1G / 8G INFO General (genomic_info_filler.cpp : 141) EC coverage threshold value was calculated as 7
0:01:43.135 1G / 8G INFO General (genomic_info_filler.cpp : 142) Trusted kmer low bound: 0
0:01:43.135 1G / 8G INFO StageManager (stage.cpp : 126) STAGE == Gap Closer
0:01:43.135 1G / 8G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:01:44.451 1G / 8G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:01:48.400 1G / 8G INFO General (gap_closer.cpp : 138) Used 748859 paired reads
0:01:48.400 1G / 8G INFO General (gap_closer.cpp : 140) Merging paired indices
0:01:48.672 1G / 8G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:01:52.594 1G / 8G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 23 gaps after checking 13690 candidates
0:01:52.707 1G / 8G INFO StageManager (stage.cpp : 126) STAGE == Simplification
0:01:52.709 580M / 8G INFO General (simplification.cpp : 387) Graph simplification started
0:01:52.709 580M / 8G INFO General (simplification.cpp : 77) PROCEDURE == InitialCleaning
0:01:52.710 580M / 8G INFO General (graph_simplification.hpp : 645) Flanking coverage based disconnection disabled
0:01:52.710 580M / 8G INFO General (simplification.cpp : 356) Running Self conjugate edge remover
0:01:52.874 580M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:01:52.874 580M / 8G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
0:01:52.875 580M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 1
0:01:52.875 580M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:01:56.765 596M / 8G INFO General (simplification.cpp : 358) Triggered 431411 times
0:01:56.765 596M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:08.093 620M / 8G INFO General (simplification.cpp : 358) Triggered 5712 times
0:02:08.093 620M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:08.686 620M / 8G INFO General (simplification.cpp : 358) Triggered 1 times
0:02:08.686 620M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 2
0:02:08.686 620M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:08.734 620M / 8G INFO General (simplification.cpp : 358) Triggered 357 times
0:02:08.734 620M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:08.758 620M / 8G INFO General (simplification.cpp : 358) Triggered 4 times
0:02:08.758 620M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:16.717 628M / 8G INFO General (simplification.cpp : 358) Triggered 259949 times
0:02:16.717 628M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 3
0:02:16.717 628M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:17.225 628M / 8G INFO General (simplification.cpp : 358) Triggered 22628 times
0:02:17.225 628M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:33.100 668M / 8G INFO General (simplification.cpp : 358) Triggered 9161 times
0:02:33.100 668M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:34.618 668M / 8G INFO General (simplification.cpp : 358) Triggered 47863 times
0:02:34.618 668M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 4
0:02:34.618 668M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:34.701 668M / 8G INFO General (simplification.cpp : 358) Triggered 2202 times
0:02:34.701 668M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:42.253 688M / 8G INFO General (simplification.cpp : 358) Triggered 5648 times
0:02:42.253 688M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:42.810 664M / 8G INFO General (simplification.cpp : 358) Triggered 17039 times
0:02:42.810 664M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 5
0:02:42.810 664M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:42.835 664M / 8G INFO General (simplification.cpp : 358) Triggered 421 times
0:02:42.835 664M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:46.451 680M / 8G INFO General (simplification.cpp : 358) Triggered 2993 times
0:02:46.451 680M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:46.840 664M / 8G INFO General (simplification.cpp : 358) Triggered 11475 times
0:02:46.841 664M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 6
0:02:46.841 664M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:46.855 660M / 8G INFO General (simplification.cpp : 358) Triggered 162 times
0:02:46.855 660M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:49.947 660M / 8G INFO General (simplification.cpp : 358) Triggered 2785 times
0:02:49.947 660M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:50.166 652M / 8G INFO General (simplification.cpp : 358) Triggered 6414 times
0:02:50.166 652M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 7
0:02:50.166 652M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:50.176 652M / 8G INFO General (simplification.cpp : 358) Triggered 74 times
0:02:50.176 652M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:51.978 652M / 8G INFO General (simplification.cpp : 358) Triggered 1814 times
0:02:51.978 652M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:52.107 632M / 8G INFO General (simplification.cpp : 358) Triggered 3805 times
0:02:52.107 632M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 8
0:02:52.107 632M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:52.115 632M / 8G INFO General (simplification.cpp : 358) Triggered 41 times
0:02:52.115 632M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:53.199 636M / 8G INFO General (simplification.cpp : 358) Triggered 1206 times
0:02:53.199 636M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:53.301 624M / 8G INFO General (simplification.cpp : 358) Triggered 2750 times
0:02:53.301 624M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 9
0:02:53.301 624M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:53.307 624M / 8G INFO General (simplification.cpp : 358) Triggered 29 times
0:02:53.307 624M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:54.137 616M / 8G INFO General (simplification.cpp : 358) Triggered 1061 times
0:02:54.137 616M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:54.207 608M / 8G INFO General (simplification.cpp : 358) Triggered 1869 times
0:02:54.207 608M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 10
0:02:54.207 608M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:54.220 608M / 8G INFO General (simplification.cpp : 358) Triggered 48 times
0:02:54.220 608M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:54.893 604M / 8G INFO General (simplification.cpp : 358) Triggered 727 times
0:02:54.893 604M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:54.956 596M / 8G INFO General (simplification.cpp : 358) Triggered 1367 times
0:02:54.956 596M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 11
0:02:54.956 596M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:54.959 596M / 8G INFO General (simplification.cpp : 358) Triggered 11 times
0:02:54.959 596M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:55.308 596M / 8G INFO General (simplification.cpp : 358) Triggered 584 times
0:02:55.309 596M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:55.309 596M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:55.309 596M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 12
0:02:55.309 596M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:55.310 596M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:55.310 596M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:55.310 596M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:55.310 596M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:55.310 596M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:55.310 596M / 8G INFO General (simplification.cpp : 167) PROCEDURE == Post simplification
0:02:55.310 596M / 8G INFO General (graph_simplification.hpp : 447) Disconnection of relatively low covered edges disabled
0:02:55.310 596M / 8G INFO General (graph_simplification.hpp : 477) Complex tip clipping disabled
0:02:55.310 596M / 8G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
0:02:55.310 596M / 8G INFO General (simplification.cpp : 301) Iteration 1
0:02:55.310 596M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:55.320 596M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:55.320 596M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:55.455 588M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:55.455 588M / 8G INFO General (simplification.cpp : 301) Iteration 2
0:02:55.455 588M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:55.464 588M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:55.464 588M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:55.600 588M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:55.600 588M / 8G INFO General (simplification.cpp : 333) Disrupting self-conjugate edges
0:02:55.646 588M / 8G INFO StageManager (stage.cpp : 126) STAGE == Gap Closer
0:02:55.646 588M / 8G INFO General (graph_pack.hpp : 99) Index refill
0:02:55.646 588M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:02:55.646 588M / 8G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:02:55.646 588M / 8G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:02:55.646 588M / 8G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.26774 Gb
0:02:55.646 588M / 8G INFO General (kmer_splitters.hpp : 82) Using cell size of 262144
0:02:55.859 8G / 8G INFO General (edge_index_builders.hpp : 75) Processed 98286 edges
0:02:55.859 8G / 8G INFO General (edge_index_builders.hpp : 80) Used 98286 sequences.
0:02:55.867 588M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:02:55.931 588M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 3000333 kmers in total.
0:02:55.931 588M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:02:55.971 588M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:02:56.096 600M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:02:56.275 600M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 1399632 bytes occupied (3.73194 bits per kmer).
0:02:56.298 672M / 8G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from graph, this takes a while.
0:02:56.436 672M / 8G INFO General (edge_index.hpp : 91) Index refilled
0:02:56.437 672M / 8G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:02:56.492 672M / 8G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:03:04.424 672M / 8G INFO General (gap_closer.cpp : 138) Used 748859 paired reads
0:03:04.424 672M / 8G INFO General (gap_closer.cpp : 140) Merging paired indices
0:03:04.440 672M / 8G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:03:04.522 672M / 8G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 6 gaps after checking 298 candidates
0:03:04.537 672M / 8G INFO StageManager (stage.cpp : 126) STAGE == Simplification Cleanup
0:03:04.537 672M / 8G INFO General (simplification.cpp : 547) Removing isolated edges
0:03:06.188 576M / 8G INFO General (simplification.cpp : 570) Counting average coverage
0:03:06.201 576M / 8G INFO General (simplification.cpp : 575) Average coverage = 625.263
0:03:06.201 576M / 8G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
0:03:06.201 576M / 8G INFO General (contig_output_stage.cpp : 40) Writing GFA to /tmp/tmp.rzr9ZjS78c//K55/assembly_graph_with_scaffolds.gfa
0:03:06.269 572M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K55/before_rr.fasta
0:03:06.354 572M / 8G INFO General (contig_output_stage.cpp : 50) Outputting FastG graph to /tmp/tmp.rzr9ZjS78c//K55/assembly_graph.fastg
0:03:06.606 572M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K55/simplified_contigs.fasta
0:03:06.691 572M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K55/final_contigs.fasta
0:03:06.776 572M / 8G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
0:03:06.776 572M / 8G INFO General (contig_output_stage.cpp : 40) Writing GFA to /tmp/tmp.rzr9ZjS78c//K55/assembly_graph_with_scaffolds.gfa
0:03:06.838 572M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K55/before_rr.fasta
0:03:06.924 572M / 8G INFO General (contig_output_stage.cpp : 50) Outputting FastG graph to /tmp/tmp.rzr9ZjS78c//K55/assembly_graph.fastg
0:03:07.201 572M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K55/simplified_contigs.fasta
0:03:07.292 572M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K55/final_contigs.fasta
0:03:07.393 572M / 8G INFO General (launch.hpp : 137) SPAdes finished
0:03:08.544 32M / 8G INFO General (main.cpp : 110) Assembling time: 0 hours 3 minutes 8 seconds
== Running assembler: K95
0:00:00.000 4M / 4M INFO General (main.cpp : 76) Loading config from /tmp/tmp.rzr9ZjS78c/K95/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 76) Loading config from /tmp/tmp.rzr9ZjS78c/K95/configs/careful_mode.info
0:00:00.000 4M / 4M INFO General (memory_limit.hpp : 51) Memory limit set to 31 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 91) Assembling dataset (/tmp/tmp.rzr9ZjS78c/dataset.info) with K=95
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 : 61) Two-step RR enabled: 0
0:00:00.000 4M / 4M INFO General (launch.hpp : 79) Will need read mapping, kmer mapper will be attached
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 126) STAGE == Construction
0:00:00.000 4M / 4M INFO General (read_converter.hpp : 67) Binary reads detected
0:00:00.000 4M / 4M INFO General (read_converter.hpp : 67) Binary reads detected
0:00:00.000 4M / 4M INFO General (graph_construction.hpp : 120) Constructing DeBruijn graph for k=95
0:00:00.000 4M / 4M INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 64 buckets using 8 threads. This might take a while.
0:00:00.000 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:00.000 4M / 4M INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.2915 Gb
0:00:00.000 4M / 4M INFO General (kmer_splitters.hpp : 82) Using cell size of 349525
0:00:05.752 6G / 6G INFO General (kmer_splitters.hpp : 291) Processed 3869949 reads
0:00:10.195 6G / 6G INFO General (kmer_splitters.hpp : 291) Processed 5702089 reads
0:00:10.700 6G / 6G INFO General (kmer_splitters.hpp : 291) Processed 5903954 reads
0:00:10.700 6G / 6G INFO General (kmer_splitters.hpp : 297) Adding contigs from previous K
0:00:10.803 32M / 6G INFO General (kmer_splitters.hpp : 310) Used 5903954 reads. Maximum read length 451
0:00:10.803 32M / 6G INFO General (kmer_splitters.hpp : 311) Average read length 202.172
0:00:10.803 32M / 6G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:11.409 32M / 6G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 28083105 kmers in total.
0:00:11.410 32M / 6G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:11.914 32M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:00:11.914 32M / 6G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:00:11.914 32M / 6G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:11.914 32M / 6G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.29036 Gb
0:00:11.914 32M / 6G INFO General (kmer_splitters.hpp : 82) Using cell size of 174762
0:00:15.467 8G / 8G INFO General (kmer_splitters.hpp : 381) Processed 28083105 kmers
0:00:15.468 8G / 8G INFO General (kmer_splitters.hpp : 386) Used 28083105 kmers.
0:00:15.480 32M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:15.979 32M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 28215774 kmers in total.
0:00:15.979 32M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:16.469 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:00:17.868 32M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:00:23.595 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 13091856 bytes occupied (3.71193 bits per kmer).
0:00:23.613 60M / 8G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 87) Building k-mer extensions from k+1-mers
0:00:26.127 60M / 8G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 91) Building k-mer extensions from k+1-mers finished.
0:00:26.128 60M / 8G INFO General (graph_construction.hpp : 136) Condensing graph
0:00:26.144 60M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:00:30.232 164M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1261792 sequences extracted
0:00:32.662 164M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:00:33.506 164M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:00:34.367 492M / 8G INFO General (graph_construction.hpp : 141) Building index with from graph
0:00:34.367 492M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:00:34.367 492M / 8G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:00:34.367 492M / 8G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:00:34.367 492M / 8G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.27165 Gb
0:00:34.367 492M / 8G INFO General (kmer_splitters.hpp : 82) Using cell size of 174762
0:00:36.112 8G / 8G INFO General (edge_index_builders.hpp : 75) Processed 2523583 edges
0:00:36.112 8G / 8G INFO General (edge_index_builders.hpp : 80) Used 2523583 sequences.
0:00:36.119 492M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:00:36.603 492M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 28083105 kmers in total.
0:00:36.603 492M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:00:37.094 492M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:00:38.311 492M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:00:46.530 492M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 13030248 bytes occupied (3.71191 bits per kmer).
0:00:46.748 1G / 8G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from graph, this takes a while.
0:00:48.379 1G / 8G INFO General (edge_index.hpp : 91) Index refilled
0:00:49.006 1G / 8G INFO General (graph_construction.hpp : 173) Filling coverage index
0:00:49.006 1G / 8G INFO General (edge_index_builders.hpp : 183) Collecting k-mer coverage information from reads, this takes a while.
0:01:31.306 1G / 8G INFO General (graph_construction.hpp : 175) Filling coverage and flanking coverage from index
0:01:33.406 1G / 8G INFO General (construction.cpp : 30) Figured out: read length = 451
0:01:33.406 1G / 8G INFO StageManager (stage.cpp : 126) STAGE == EC Threshold Finding
0:01:33.781 1G / 8G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 70
0:01:33.781 1G / 8G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 71
0:01:33.781 1G / 8G WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable
0:01:33.781 1G / 8G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 71. Coverage mad: 27.9343
0:01:33.781 1G / 8G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:33.953 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:34.444 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:36.227 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:40.250 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:46.452 1G / 8G INFO General (kmer_coverage_model.cpp : 295) ... iteration 32
0:01:55.016 1G / 8G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 15.3052. Fitted coverage std. dev: 7.03021
0:01:55.016 1G / 8G WARN General (kmer_coverage_model.cpp : 327) Valley value was estimated improperly, reset to 3
0:01:55.019 1G / 8G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1
0:01:55.019 1G / 8G WARN General (kmer_coverage_model.cpp : 366) Failed to determine erroneous kmer threshold. Threshold set to: 3
0:01:55.019 1G / 8G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 2831080
0:01:55.019 1G / 8G INFO General (genomic_info_filler.cpp : 129) Failed to estimate mean coverage
0:01:55.020 1G / 8G INFO General (genomic_info_filler.cpp : 141) EC coverage threshold value was calculated as 3
0:01:55.020 1G / 8G INFO General (genomic_info_filler.cpp : 142) Trusted kmer low bound: 0
0:01:55.020 1G / 8G INFO StageManager (stage.cpp : 126) STAGE == Gap Closer
0:01:55.020 1G / 8G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:01:56.277 1G / 8G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:01:58.274 1G / 8G INFO General (gap_closer.cpp : 138) Used 748859 paired reads
0:01:58.274 1G / 8G INFO General (gap_closer.cpp : 140) Merging paired indices
0:01:58.816 1G / 8G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:02:01.848 1G / 8G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 38 gaps after checking 10291 candidates
0:02:01.987 1G / 8G INFO StageManager (stage.cpp : 126) STAGE == Simplification
0:02:01.990 464M / 8G INFO General (simplification.cpp : 387) Graph simplification started
0:02:01.991 464M / 8G INFO General (simplification.cpp : 77) PROCEDURE == InitialCleaning
0:02:01.991 464M / 8G INFO General (simplification.cpp : 50) Most init cleaning disabled on main iteration
0:02:01.991 464M / 8G INFO General (simplification.cpp : 356) Running Self conjugate edge remover
0:02:02.134 464M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:02.134 464M / 8G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
0:02:02.135 464M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 1
0:02:02.135 464M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:06.557 472M / 8G INFO General (simplification.cpp : 358) Triggered 439292 times
0:02:06.557 472M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:14.197 500M / 8G INFO General (simplification.cpp : 358) Triggered 3783 times
0:02:14.197 500M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:14.334 500M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:14.334 500M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 2
0:02:14.334 500M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:14.344 500M / 8G INFO General (simplification.cpp : 358) Triggered 34 times
0:02:14.344 500M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:14.346 500M / 8G INFO General (simplification.cpp : 358) Triggered 1 times
0:02:14.346 500M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:14.346 500M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:14.346 500M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 3
0:02:14.346 500M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:14.346 500M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:14.346 500M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:14.346 500M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:14.346 500M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:14.346 500M / 8G INFO General (simplification.cpp : 358) Triggered 2 times
0:02:14.346 500M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 4
0:02:14.346 500M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:14.346 500M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:14.346 500M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:14.346 500M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:14.346 500M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:15.701 500M / 8G INFO General (simplification.cpp : 358) Triggered 44830 times
0:02:15.701 500M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 5
0:02:15.701 500M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:15.848 496M / 8G INFO General (simplification.cpp : 358) Triggered 7440 times
0:02:15.848 496M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:33.720 628M / 8G INFO General (simplification.cpp : 358) Triggered 9304 times
0:02:33.720 628M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:33.855 628M / 8G INFO General (simplification.cpp : 358) Triggered 4597 times
0:02:33.855 628M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 6
0:02:33.855 628M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:33.871 624M / 8G INFO General (simplification.cpp : 358) Triggered 467 times
0:02:33.871 624M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:36.602 640M / 8G INFO General (simplification.cpp : 358) Triggered 1643 times
0:02:36.602 640M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:36.690 640M / 8G INFO General (simplification.cpp : 358) Triggered 3210 times
0:02:36.690 640M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 7
0:02:36.690 640M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:36.699 640M / 8G INFO General (simplification.cpp : 358) Triggered 245 times
0:02:36.699 640M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:38.704 660M / 8G INFO General (simplification.cpp : 358) Triggered 1314 times
0:02:38.704 660M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:38.804 660M / 8G INFO General (simplification.cpp : 358) Triggered 3731 times
0:02:38.804 660M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 8
0:02:38.804 660M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:38.812 660M / 8G INFO General (simplification.cpp : 358) Triggered 209 times
0:02:38.812 660M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:41.238 680M / 8G INFO General (simplification.cpp : 358) Triggered 1916 times
0:02:41.238 680M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:41.276 680M / 8G INFO General (simplification.cpp : 358) Triggered 1462 times
0:02:41.276 680M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 9
0:02:41.276 680M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:41.280 680M / 8G INFO General (simplification.cpp : 358) Triggered 63 times
0:02:41.280 680M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:42.181 688M / 8G INFO General (simplification.cpp : 358) Triggered 758 times
0:02:42.181 688M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:42.211 688M / 8G INFO General (simplification.cpp : 358) Triggered 1149 times
0:02:42.211 688M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 10
0:02:42.211 688M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:42.269 688M / 8G INFO General (simplification.cpp : 358) Triggered 64 times
0:02:42.270 688M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:43.153 696M / 8G INFO General (simplification.cpp : 358) Triggered 620 times
0:02:43.153 696M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:43.233 692M / 8G INFO General (simplification.cpp : 358) Triggered 1056 times
0:02:43.233 692M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 11
0:02:43.233 692M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:43.236 692M / 8G INFO General (simplification.cpp : 358) Triggered 24 times
0:02:43.236 692M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:43.871 704M / 8G INFO General (simplification.cpp : 358) Triggered 654 times
0:02:43.871 704M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:43.871 704M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:43.871 704M / 8G INFO General (simplification.cpp : 410) PROCEDURE == Simplification cycle, iteration 12
0:02:43.871 704M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:43.872 704M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:43.872 704M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:43.872 704M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:43.872 704M / 8G INFO General (simplification.cpp : 356) Running Low coverage edge remover
0:02:43.872 704M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:43.872 704M / 8G INFO General (simplification.cpp : 167) PROCEDURE == Post simplification
0:02:43.872 704M / 8G INFO General (graph_simplification.hpp : 447) Disconnection of relatively low covered edges disabled
0:02:43.872 704M / 8G INFO General (graph_simplification.hpp : 477) Complex tip clipping disabled
0:02:43.872 704M / 8G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
0:02:43.872 704M / 8G INFO General (simplification.cpp : 301) Iteration 1
0:02:43.872 704M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:43.927 704M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:43.928 704M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:44.128 696M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:44.128 696M / 8G INFO General (simplification.cpp : 301) Iteration 2
0:02:44.128 696M / 8G INFO General (simplification.cpp : 356) Running Tip clipper
0:02:44.183 696M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:44.183 696M / 8G INFO General (simplification.cpp : 356) Running Bulge remover
0:02:44.386 696M / 8G INFO General (simplification.cpp : 358) Triggered 0 times
0:02:44.386 696M / 8G INFO General (simplification.cpp : 333) Disrupting self-conjugate edges
0:02:44.620 696M / 8G INFO StageManager (stage.cpp : 126) STAGE == Gap Closer
0:02:44.620 696M / 8G INFO General (graph_pack.hpp : 99) Index refill
0:02:44.620 696M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 289) Building kmer index
0:02:44.620 696M / 8G INFO General (kmer_index_builder.hpp : 106) Splitting kmer instances into 128 buckets using 8 threads. This might take a while.
0:02:44.620 696M / 8G INFO General (file_limit.hpp : 32) Open file limit set to 1048576
0:02:44.620 696M / 8G INFO General (kmer_splitters.hpp : 74) Memory available for splitting buffers: 1.26335 Gb
0:02:44.620 696M / 8G INFO General (kmer_splitters.hpp : 82) Using cell size of 174762
0:02:45.373 8G / 8G INFO General (edge_index_builders.hpp : 75) Processed 483696 edges
0:02:45.373 8G / 8G INFO General (edge_index_builders.hpp : 80) Used 483696 sequences.
0:02:45.381 696M / 8G INFO General (kmer_index_builder.hpp : 109) Starting k-mer counting.
0:02:45.615 696M / 8G INFO General (kmer_index_builder.hpp : 115) K-mer counting done. There are 12948795 kmers in total.
0:02:45.615 696M / 8G INFO General (kmer_index_builder.hpp : 121) Merging temporary buckets.
0:02:45.844 696M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 298) Building perfect hash indices
0:02:46.425 712M / 8G INFO General (kmer_index_builder.hpp : 137) Merging final buckets.
0:02:48.359 712M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 320) Index built. Total 6012160 bytes occupied (3.71442 bits per kmer).
0:02:48.459 1012M / 8G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from graph, this takes a while.
0:02:49.134 1012M / 8G INFO General (edge_index.hpp : 91) Index refilled
0:02:49.134 1012M / 8G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:02:49.569 1G / 8G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:02:54.574 1G / 8G INFO General (gap_closer.cpp : 138) Used 748859 paired reads
0:02:54.574 1G / 8G INFO General (gap_closer.cpp : 140) Merging paired indices
0:02:54.776 1G / 8G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:02:55.270 1G / 8G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 2 gaps after checking 291 candidates
0:02:55.327 1G / 8G INFO StageManager (stage.cpp : 126) STAGE == Simplification Cleanup
0:02:55.327 1G / 8G INFO General (simplification.cpp : 547) Removing isolated edges
0:03:06.677 836M / 8G INFO General (simplification.cpp : 570) Counting average coverage
0:03:06.688 836M / 8G INFO General (simplification.cpp : 575) Average coverage = 332.282
0:03:06.688 836M / 8G INFO StageManager (stage.cpp : 126) STAGE == Mismatch Correction
0:03:06.688 836M / 8G INFO General (graph_pack.hpp : 108) Normalizing k-mer map. Total 3853170 kmers to process
0:03:08.848 832M / 8G INFO General (graph_pack.hpp : 110) Normalizing done
0:03:40.582 1G / 8G INFO General (mismatch_shall_not_pass.hp: 187) Finished collecting potential mismatches positions
0:03:41.843 896M / 8G INFO General (mismatch_shall_not_pass.hp: 284) All edges processed
0:03:41.958 836M / 8G INFO General (mismatch_correction.cpp : 26) Corrected 0 nucleotides
0:03:41.958 836M / 8G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
0:03:41.958 836M / 8G INFO General (contig_output_stage.cpp : 40) Writing GFA to /tmp/tmp.rzr9ZjS78c//K95/assembly_graph_with_scaffolds.gfa
0:03:42.020 832M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K95/before_rr.fasta
0:03:42.099 832M / 8G INFO General (contig_output_stage.cpp : 50) Outputting FastG graph to /tmp/tmp.rzr9ZjS78c//K95/assembly_graph.fastg
0:03:42.332 832M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K95/simplified_contigs.fasta
0:03:42.412 832M / 8G INFO General (contig_output.hpp : 22) Outputting contigs to /tmp/tmp.rzr9ZjS78c//K95/intermediate_contigs.fasta
0:03:42.491 832M / 8G INFO StageManager (stage.cpp : 126) STAGE == Paired Information Counting
0:03:42.616 836M / 8G INFO General (graph_pack.hpp : 108) Normalizing k-mer map. Total 3853170 kmers to process
0:03:42.616 836M / 8G INFO General (graph_pack.hpp : 110) Normalizing done
0:03:42.622 836M / 8G INFO General (pair_info_count.cpp : 317) Min edge length for estimation: 88
0:03:42.622 836M / 8G INFO General (pair_info_count.cpp : 328) Estimating insert size for library #0
0:03:42.622 836M / 8G INFO General (pair_info_count.cpp : 176) Estimating insert size (takes a while)
0:03:42.663 980M / 8G INFO General (short_read_mapper.hpp : 88) Selecting usual mapper
0:03:49.794 980M / 8G INFO General (sequence_mapper_notifier.h: 99) Total 748859 reads processed
0:03:51.305 980M / 8G INFO General (pair_info_count.cpp : 194) Edge pairs: 67108864 (rough upper limit)
0:03:51.305 980M / 8G INFO General (pair_info_count.cpp : 198) 10751 paired reads (1.43565% of all) aligned to long edges
0:03:51.306 836M / 8G INFO General (pair_info_count.cpp : 351) Insert size = 393.557, deviation = 133.279, left quantile = 208, right quantile = 561, read length = 150
0:03:51.354 1G / 8G INFO General (pair_info_count.cpp : 368) Filtering data for library #0
0:03:51.354 1G / 8G INFO General (short_read_mapper.hpp : 88) Selecting usual mapper
0:04:07.721 1G / 8G INFO General (sequence_mapper_notifier.h: 99) Total 748859 reads processed
0:04:07.722 1G / 8G INFO General (pair_info_count.cpp : 380) Mapping library #0
0:04:07.722 1G / 8G INFO General (pair_info_count.cpp : 382) Mapping paired reads (takes a while)
0:04:07.722 1G / 8G INFO General (pair_info_count.cpp : 275) Left insert size quantile 208, right insert size quantile 561, filtering threshold 2, rounding threshold 0
0:04:07.727 1G / 8G INFO General (short_read_mapper.hpp : 88) Selecting usual mapper
0:04:41.614 2G / 8G INFO General (sequence_mapper_notifier.h: 99) Total 748859 reads processed
0:04:41.622 1G / 8G INFO General (pair_info_count.cpp : 389) Mapping single reads of library #1
0:04:41.622 1G / 8G INFO General (short_read_mapper.hpp : 88) Selecting usual mapper
0:04:53.076 3G / 8G INFO General (sequence_mapper_notifier.h: 99) Total 1442914 reads processed
0:04:53.076 3G / 8G INFO General (pair_info_count.cpp : 391) Total paths obtained from single reads: 744606
0:04:53.076 3G / 8G INFO StageManager (stage.cpp : 126) STAGE == Distance Estimation
0:04:53.076 3G / 8G INFO General (distance_estimation.cpp : 224) Processing library #0
0:04:53.076 3G / 8G INFO General (distance_estimation.cpp : 130) Weight Filter Done
0:04:53.076 3G / 8G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SIMPLE distance estimator
0:16:08.153 3G / 8G INFO General (distance_estimation.cpp : 35) Filtering info
0:16:08.153 3G / 8G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 19362703
0:16:13.959 3G / 8G INFO General (pair_info_filters.hpp : 263) Done filtering
0:16:13.960 3G / 8G INFO General (distance_estimation.cpp : 172) Refining clustered pair information
0:16:15.424 3G / 8G INFO General (distance_estimation.cpp : 174) The refining of clustered pair information has been finished
0:16:15.424 3G / 8G INFO General (distance_estimation.cpp : 176) Improving paired information
0:17:10.776 3G / 8G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 2482494; contradictional = 0
0:19:27.442 3G / 8G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 1060743; contradictional = 0
0:19:27.442 3G / 8G INFO General (distance_estimation.cpp : 183) Filling scaffolding index
0:19:27.442 3G / 8G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SMOOTHING distance estimator
0:31:10.092 3G / 8G INFO General (distance_estimation.cpp : 35) Filtering info
0:31:10.092 3G / 8G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 2481965
0:31:10.812 4G / 8G INFO General (pair_info_filters.hpp : 263) Done filtering
0:31:10.812 3G / 8G INFO General (distance_estimation.cpp : 228) Clearing raw paired index
0:31:12.625 2G / 8G INFO StageManager (stage.cpp : 126) STAGE == Repeat Resolving
0:31:23.163 2G / 8G INFO General (repeat_resolving.cpp : 69) Using Path-Extend repeat resolving
0:31:23.163 2G / 8G INFO General (launcher.cpp : 478) ExSPAnder repeat resolving tool started
0:31:23.233 3G / 8G INFO General (launcher.cpp : 393) Creating main extenders, unique edge length = 2000
0:32:47.983 15G / 16G INFO General (extenders_logic.cpp : 275) Estimated coverage of library #0 is 125.61
0:32:47.987 15G / 16G INFO General (extenders_logic.cpp : 275) Estimated coverage of library #0 is 125.61
0:32:48.003 15G / 16G INFO General (extenders_logic.cpp : 33) resolvable_repeat_length_bound set to 10000
0:37:56.943 15G / 16G INFO General (extenders_logic.cpp : 472) Using 1 paired-end library
0:37:56.943 15G / 16G INFO General (extenders_logic.cpp : 473) Using 1 paired-end scaffolding library
0:37:56.943 15G / 16G INFO General (extenders_logic.cpp : 474) Using 1 single read library
0:37:56.943 15G / 16G INFO General (launcher.cpp : 421) Total number of extenders is 4
0:37:56.943 15G / 16G INFO General (path_extender.hpp : 867) Processed 0 paths from 21258 (0%)
0:37:57.131 15G / 16G INFO General (path_extender.hpp : 865) Processed 128 paths from 21258 (0%)
0:38:40.988 15G / 16G INFO General (path_extender.hpp : 865) Processed 256 paths from 21258 (1%)
0:52:38.885 15G / 16G INFO General (path_extender.hpp : 865) Processed 512 paths from 21258 (2%)
1:35:42.200 15G / 16G INFO General (path_extender.hpp : 865) Processed 1024 paths from 21258 (4%)
2:51:25.856 15G / 16G INFO General (path_extender.hpp : 865) Processed 2048 paths from 21258 (9%)
2:55:39.446 15G / 16G INFO General (path_extender.hpp : 867) Processed 2126 paths from 21258 (10%)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment