spades
spades copied to clipboard
Published
20 hours ago •
ablab
ablab
cloudspades: spades-core finished abnormally, err code: -8
I'm running cloudspades with simulated metagenomes (10 reference genomes per metagenome, 1 mil paired-end SLR reads, reads simulated via ART).
I'm using the following command:
spades.py --meta -k auto --only-assembler -t 12 -m 256 --tmp-dir /ebio/abt3_scratch/tmp_49025743982/-o $OUTDIR --gemcode1-1 R1_cloud.fq --gemcode1-2 R2_cloud.fq
...and I get the error:
0:13:39.905 3G / 7G INFO LabeledDistributionThres (containment_index_threshol: 157) 2 training edges.
0:13:39.905 3G / 7G INFO LongEdgeScoreHistogramCo (containment_index_threshol: 75) 22 score samples
0:13:39.905 3G / 7G INFO LabeledDistributionThres (containment_index_threshol: 174) Estimated score threshold: 0
0:13:39.905 3G / 7G WARN General (construction_callers.cpp : 71) Estimated score threshold 0 is too small, setting 0.001 as default threshold
== Error == system call for: "['/ebio/abt3_projects/software/dev/haptag-mg/data_sim/bin/scripts/spades/bin/spades-core', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/config.info', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/mda_mode.info', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/meta_mode.info']" finished abnormally, err code: -8
======= SPAdes pipeline finished abnormally and WITH WARNINGS!
=== Error correction and assembling warnings:
* 0:13:39.678 3G / 7G WARN ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 59) Less than half of genome in unique edges!
* 0:13:39.905 3G / 7G WARN General (construction_callers.cpp : 71) Estimated score threshold 0 is too small, setting 0.001 as default threshold
======= Warnings saved to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/warnings.log
=== ERRORs:
* system call for: "['/ebio/abt3_projects/software/dev/haptag-mg/data_sim/bin/scripts/spades/bin/spades-core', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/config.info', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/mda_mode.info', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/meta_mode.info']" finished abnormally, err code: -8
In case you have troubles running SPAdes, you can write to [email protected]
or report an issue on our GitHub repository github.com/ablab/spades
Please provide us with params.txt and spades.log files from the output directory.
The reads work fine when using them for metaspades or megahit. The cloud-read barcodes should be fine. An example:
@835aeb3c2b9442218d7766f726c8242c BX:Z:A13B94C03D29
GAACAGATTCAGGTACGGCCCTTCAACAACGTACTTGATTTGGGTACCTTACCGTTGTCTTCCAATTCCAGAAACCTGAAAGAAGTGACGGTGAAAGGCATGCAGGAACGCGTGGAGCAGAAAGCCGATACACTGATTTACAACGCCGAT
+
CCCGGGGGGGGC8JJJJJGJG=GGJJCJGJJGGJGJGGGJJJJJG8JCJC8(CGGJCGGGJGGCCJGGC1JCGGC1GJ=C=CCCCGGGGGGGGGGGCGGGJCGCGGCCGCGGGG1GCGCGGGGCCCCGGGGCGGCGCG==GGG1CGGGGG
@835aeb3c2b9442218d7766f726c8242c BX:Z:A13B94C03D29
GATTTGCCATATATAGTGGAAATGTTGACTTGATCTTTGATCTCTTCGCCTTCTTTATCTGCTAATAAACTTTTTTCGGTATAGAAAGAGCTTGTCTTAGTAATTATTAGCGTTCCATTTCCCGAATAGCCGGGATCTAAAGGCTGATTT
+
CCCGGCGGGGGGGJJJJJJJ1JJGJJJJGCJJ=JGJJJ(JJJGJJJGJJ18JGG=GCG=GG=CGJGCGGCGG=GGJG=GG=GGGCGGCCGGGGGGGCGGGJ1C=GG8GGGG=C=GGGCGGCCGG=GGCCCGCCGCCGCGGGGGCGCGCGC
The full output
Command line: ./bin/scripts/spades/spades.py --meta -k auto --only-assembler -t 12 -m 256 --tmp-dir /ebio/abt3_scratch/haptag-mg_49025743982/asmbl/cloudmetaspades_tmp/1/1/1000000 -o /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1 --gemcode1-1 /ebio/abt3_scratch/haptag-mg_49025743982/1/1/1000000/sim_reads/1/R1_cloud.fq --gemcode1-2 /ebio/abt3_scratch/haptag-mg_49025743982/1/1/1000000/sim_reads/1/R2_cloud.fq
System information:
SPAdes version: 3.12.0-dev
Python version: 2.7.15
OS: Linux-4.19.121-x86_64-with-debian-buster-sid
Output dir: /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1
Mode: ONLY assembling (without read error correction)
Debug mode is turned OFF
Dataset parameters:
Metagenomic mode
Reads:
Library number: 1, library type: clouds10x
orientation: fr
left reads: ['/ebio/abt3_scratch/haptag-mg_49025743982/1/1/1000000/sim_reads/1/R1_cloud.fq']
right reads: ['/ebio/abt3_scratch/haptag-mg_49025743982/1/1/1000000/sim_reads/1/R2_cloud.fq']
interlaced reads: not specified
single reads: not specified
merged reads: not specified
Assembly parameters:
k: [21, 33, 55]
Repeat resolution is enabled
Mismatch careful mode is turned OFF
MismatchCorrector will be SKIPPED
Coverage cutoff is turned OFF
Other parameters:
Dir for temp files: /ebio/abt3_scratch/haptag-mg_49025743982/asmbl/cloudmetaspades_tmp/1/1/1000000
Threads: 12
Memory limit (in Gb): 256
======= SPAdes pipeline started. Log can be found here: /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/spades.log
===== Assembling started.
== Running assembler: K21
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K21/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K21/configs/mda_mode.info
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K21/configs/meta_mode.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 256 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/master, git revision 33c36825c7e5dc2874918cad6c1a01a3197451c1
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/dataset.info) with K=21
0:00:00.000 4M / 4M INFO General (launch.hpp : 54) SPAdes started
0:00:00.000 4M / 4M INFO General (launch.hpp : 61) Starting from stage: construction
0:00:00.000 4M / 4M INFO General (launch.hpp : 64) Two-step RR enabled: 0
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.006 4M / 4M INFO General (read_converter.hpp : 77) Converting reads to binary format for library #0 (takes a while)
0:00:00.006 4M / 4M INFO General (read_converter.hpp : 78) Converting paired reads
0:00:00.284 112M / 112M INFO General (binary_converter.hpp : 93) 16384 reads processed
0:00:00.478 124M / 124M INFO General (binary_converter.hpp : 93) 32768 reads processed
0:00:00.838 148M / 148M INFO General (binary_converter.hpp : 93) 65536 reads processed
0:00:01.548 196M / 196M INFO General (binary_converter.hpp : 93) 131072 reads processed
0:00:03.012 292M / 292M INFO General (binary_converter.hpp : 93) 262144 reads processed
0:00:07.266 328M / 328M INFO General (binary_converter.hpp : 93) 524288 reads processed
0:00:15.625 148M / 328M INFO General (binary_converter.hpp : 117) 1000000 reads written
0:00:15.684 4M / 328M INFO General (read_converter.hpp : 87) Converting single reads
0:00:15.819 148M / 328M INFO General (binary_converter.hpp : 117) 0 reads written
0:00:15.827 4M / 328M INFO General (read_converter.hpp : 95) Converting merged reads
0:00:15.956 148M / 328M INFO General (binary_converter.hpp : 117) 0 reads written
0:00:16.218 4M / 328M INFO General (construction.cpp : 111) Max read length 150
0:00:16.218 4M / 328M INFO General (construction.cpp : 117) Average read length 149.998
0:00:16.218 4M / 328M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:16.219 4M / 328M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 144 files using 12 threads. This might take a while.
0:00:16.220 4M / 328M INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:00:16.220 4M / 328M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.111 Gb
0:00:16.220 4M / 328M INFO General (kmer_splitters.hpp : 97) Using cell size of 466033
0:00:28.948 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 4000000 reads
0:00:28.948 6G / 6G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:29.202 48M / 6G INFO General (kmer_splitters.hpp : 308) Used 4000000 reads
0:00:29.202 48M / 6G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:34.491 48M / 6G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 111046590 kmers in total.
0:00:34.491 48M / 6G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:41.321 48M / 6G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:41.322 48M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:41.322 48M / 6G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 192 files using 12 threads. This might take a while.
0:00:41.324 48M / 6G INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:00:41.324 48M / 6G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.10981 Gb
0:00:41.324 48M / 6G INFO General (kmer_splitters.hpp : 97) Using cell size of 349525
0:00:53.750 6G / 6G INFO General (kmer_splitters.hpp : 380) Processed 111046590 kmers
0:00:53.750 6G / 6G INFO General (kmer_splitters.hpp : 385) Used 111046590 kmers.
0:00:54.060 48M / 6G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:01.728 48M / 6G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 110824843 kmers in total.
0:01:01.728 48M / 6G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:09.998 48M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:17.995 64M / 6G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:19.930 64M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 51397784 bytes occupied (3.7102 bits per kmer).
0:01:20.043 172M / 6G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:32.176 172M / 6G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:32.177 172M / 6G INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping
0:01:32.177 172M / 6G INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K)
0:01:32.177 172M / 6G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping
0:01:59.080 204M / 6G INFO Early tip clipping (early_simplification.hpp : 184) 3927466 22-mers were removed by early tip clipper
0:01:59.080 204M / 6G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:59.097 204M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:02:17.988 300M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1337032 sequences extracted
0:02:25.629 300M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:02:30.229 300M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 29 loops collected
0:02:31.063 608M / 6G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:02:31.063 608M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:02:31.063 608M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:36.678 664M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 51498592 bytes occupied (3.71005 bits per kmer).
0:02:37.040 1G / 6G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:02:51.210 1G / 6G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:03:02.502 1G / 6G INFO General (construction.cpp : 464) Processed 2673524 edges
0:03:02.906 448M / 6G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:03:06.127 444M / 6G INFO ThresholdFinder (ec_threshold_finder.hpp : 114) Bucket size: 5
0:03:06.127 444M / 6G INFO General (genomic_info_filler.cpp : 98) Average edge coverage: 2.36558
0:03:06.127 444M / 6G INFO General (genomic_info_filler.cpp : 99) Graph threshold: 63
0:03:06.127 444M / 6G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 2.36558
0:03:06.127 444M / 6G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:03:06.127 444M / 6G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:03:06.127 444M / 6G INFO General (simplification.cpp : 333) Graph simplification started
0:03:06.127 444M / 6G INFO General (simplification.cpp : 87) PROCEDURE == InitialCleaning
0:03:06.127 444M / 6G INFO General (graph_simplification.hpp : 630) Flanking coverage based disconnection disabled
0:03:06.127 444M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:03:06.283 444M / 6G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:03:06.283 444M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:03:06.514 444M / 6G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 215 times
0:03:06.514 444M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:03:06.829 444M / 6G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 4435 times
0:03:06.829 444M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:03:07.059 444M / 6G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 0 times
0:03:07.061 444M / 6G INFO General (graph_simplification.hpp : 602) Creating parallel br instance
0:03:07.062 444M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 1
0:03:07.062 444M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:07.301 444M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 824 times
0:03:07.301 444M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:32.747 488M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 345030 times
0:03:32.747 488M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:32.840 488M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:32.840 488M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 2
0:03:32.840 488M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:33.110 472M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 3562 times
0:03:33.110 472M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:33.119 472M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 15 times
0:03:33.119 472M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:33.401 472M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 7513 times
0:03:33.401 472M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 3
0:03:33.401 472M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:33.416 468M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 212 times
0:03:33.417 468M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:33.471 468M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 251 times
0:03:33.471 468M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:33.599 468M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 3505 times
0:03:33.599 468M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 4
0:03:33.599 468M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:33.684 468M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 36 times
0:03:33.684 468M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:33.848 468M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 100 times
0:03:33.849 468M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:33.930 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:33.930 464M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 5
0:03:33.930 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:33.931 464M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 6
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:33.931 464M / 6G INFO General (simplification.cpp : 174) PROCEDURE == Post simplification
0:03:33.931 464M / 6G INFO General (graph_simplification.hpp : 602) Creating parallel br instance
0:03:33.931 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:03:34.133 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 2079 times
0:03:34.133 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:03:34.259 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 190 times
0:03:34.259 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:03:34.378 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 7 times
0:03:34.378 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:03:37.373 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 18 times
0:03:37.373 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:37.457 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 98 times
0:03:37.457 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:03:38.525 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 24676 times
0:03:38.525 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:38.643 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 75 times
0:03:38.643 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:03:38.739 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 2 times
0:03:38.739 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:03:38.848 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 60 times
0:03:38.849 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:03:38.946 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 28 times
0:03:38.946 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:03:39.049 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times
0:03:39.049 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:03:41.369 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 3 times
0:03:41.369 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:41.445 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 27 times
0:03:41.445 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:03:41.528 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 197 times
0:03:41.528 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:41.634 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 4 times
0:03:41.634 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:03:41.738 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times
0:03:41.738 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:03:41.839 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 0 times
0:03:41.839 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:03:41.840 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 0 times
0:03:41.840 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:03:41.944 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times
0:03:41.944 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 0 times
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:03:44.302 464M / 6G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times
0:03:44.302 464M / 6G INFO General (simplification.cpp : 309) Running Hidden EC remover (meta)
0:03:44.382 464M / 6G INFO General (simplification.cpp : 313) Disrupting self-conjugate edges
0:03:44.973 460M / 6G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:03:44.973 460M / 6G INFO General (simplification.cpp : 438) Removing isolated edges
0:03:45.048 460M / 6G INFO General (simplification.cpp : 461) Counting average coverage
0:03:45.344 460M / 6G INFO General (simplification.cpp : 467) Average coverage = 2.63917
0:03:45.344 460M / 6G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:45.344 460M / 6G INFO General (contig_output_stage.cpp : 40) Writing GFA to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/assembly_graph_with_scaffolds.gfa
0:03:47.204 460M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/before_rr.fasta
0:03:50.590 460M / 6G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/assembly_graph.fastg
0:03:57.255 460M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/simplified_contigs.fasta
0:03:59.431 460M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/final_contigs.fasta
0:04:10.201 460M / 6G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:04:10.201 460M / 6G INFO General (contig_output_stage.cpp : 40) Writing GFA to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/assembly_graph_with_scaffolds.gfa
0:04:12.118 460M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/before_rr.fasta
0:04:14.283 460M / 6G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/assembly_graph.fastg
0:04:20.604 460M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/simplified_contigs.fasta
0:04:24.295 460M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K21/final_contigs.fasta
0:04:26.523 460M / 6G INFO General (launch.hpp : 141) SPAdes finished
0:04:27.848 48M / 6G INFO General (main.cpp : 108) Assembling time: 0 hours 4 minutes 27 seconds
Max read length detected as 150
== Running assembler: K33
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K33/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K33/configs/mda_mode.info
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K33/configs/meta_mode.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 256 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/master, git revision 33c36825c7e5dc2874918cad6c1a01a3197451c1
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/dataset.info) with K=33
0:00:00.000 4M / 4M INFO General (launch.hpp : 54) SPAdes started
0:00:00.000 4M / 4M INFO General (launch.hpp : 61) Starting from stage: construction
0:00:00.000 4M / 4M INFO General (launch.hpp : 64) Two-step RR enabled: 0
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.013 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.040 4M / 4M INFO General (construction.cpp : 111) Max read length 150
0:00:00.040 4M / 4M INFO General (construction.cpp : 117) Average read length 149.998
0:00:00.040 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.041 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 144 files using 12 threads. This might take a while.
0:00:00.041 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:00:00.041 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.111 Gb
0:00:00.041 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 233016
0:00:13.510 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 4000000 reads
0:00:13.510 6G / 6G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:44.594 48M / 6G INFO General (kmer_splitters.hpp : 308) Used 4000000 reads
0:00:44.594 48M / 6G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:53.417 48M / 6G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 112505207 kmers in total.
0:00:53.417 48M / 6G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:01.954 48M / 6G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:01:01.954 48M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:01.954 48M / 6G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 192 files using 12 threads. This might take a while.
0:01:01.955 48M / 6G INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:01:01.955 48M / 6G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.10981 Gb
0:01:01.955 48M / 6G INFO General (kmer_splitters.hpp : 97) Using cell size of 174762
0:01:14.321 6G / 6G INFO General (kmer_splitters.hpp : 380) Processed 77248037 kmers
0:01:20.126 6G / 6G INFO General (kmer_splitters.hpp : 380) Processed 112505219 kmers
0:01:20.126 6G / 6G INFO General (kmer_splitters.hpp : 385) Used 112505219 kmers.
0:01:20.406 48M / 6G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:30.881 48M / 6G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 112437345 kmers in total.
0:01:30.881 48M / 6G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:42.143 48M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:50.429 68M / 6G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:54.183 68M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 52145640 bytes occupied (3.7102 bits per kmer).
0:01:54.331 176M / 6G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:02:05.973 176M / 6G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:02:05.974 172M / 6G INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping
0:02:05.974 172M / 6G INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K)
0:02:05.974 172M / 6G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping
0:02:30.240 208M / 6G INFO Early tip clipping (early_simplification.hpp : 184) 4864315 34-mers were removed by early tip clipper
0:02:30.240 208M / 6G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:02:30.259 208M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:02:47.752 272M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 963627 sequences extracted
0:02:54.882 272M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:03:00.545 272M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 46 loops collected
0:03:01.206 508M / 6G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:03:01.206 508M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:03:01.206 508M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:03:10.944 556M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 52175072 bytes occupied (3.71006 bits per kmer).
0:03:11.368 988M / 6G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:03:23.927 988M / 6G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:03:36.289 988M / 6G INFO General (construction.cpp : 464) Processed 1927173 edges
0:03:36.961 352M / 6G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:03:39.428 336M / 6G INFO ThresholdFinder (ec_threshold_finder.hpp : 114) Bucket size: 5
0:03:39.429 336M / 6G INFO General (genomic_info_filler.cpp : 98) Average edge coverage: 2.12559
0:03:39.429 336M / 6G INFO General (genomic_info_filler.cpp : 99) Graph threshold: 47
0:03:39.429 336M / 6G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 2.12559
0:03:39.429 336M / 6G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:03:39.429 336M / 6G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:03:39.429 336M / 6G INFO General (simplification.cpp : 333) Graph simplification started
0:03:39.429 336M / 6G INFO General (simplification.cpp : 87) PROCEDURE == InitialCleaning
0:03:39.429 336M / 6G INFO General (graph_simplification.hpp : 630) Flanking coverage based disconnection disabled
0:03:39.429 336M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:03:39.554 340M / 6G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 38 times
0:03:39.554 340M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:03:39.744 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 2547 times
0:03:39.744 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:03:39.990 340M / 6G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 3106 times
0:03:39.990 340M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:03:40.290 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 3454 times
0:03:40.294 348M / 6G INFO General (graph_simplification.hpp : 602) Creating parallel br instance
0:03:40.294 348M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 1
0:03:40.294 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:40.519 344M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2475 times
0:03:40.519 344M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:55.622 372M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 246010 times
0:03:55.622 372M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:55.681 372M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 37 times
0:03:55.681 372M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 2
0:03:55.681 372M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:55.821 356M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1283 times
0:03:55.821 356M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:55.822 356M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 3 times
0:03:55.822 356M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:55.845 356M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 550 times
0:03:55.845 356M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 3
0:03:55.845 356M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:55.846 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 19 times
0:03:55.846 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:55.851 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 32 times
0:03:55.851 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:55.865 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 288 times
0:03:55.865 352M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 4
0:03:55.865 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:55.935 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 18 times
0:03:55.935 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:56.009 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 13 times
0:03:56.009 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:56.074 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:56.074 352M / 6G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 5
0:03:56.074 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:56.074 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:56.074 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:56.074 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:56.074 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:56.074 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:56.074 352M / 6G INFO General (simplification.cpp : 174) PROCEDURE == Post simplification
0:03:56.074 352M / 6G INFO General (graph_simplification.hpp : 602) Creating parallel br instance
0:03:56.074 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:03:56.152 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 248 times
0:03:56.152 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:03:56.224 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 30 times
0:03:56.224 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:03:56.339 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times
0:03:56.339 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:03:58.252 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 169 times
0:03:58.252 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:58.317 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 11 times
0:03:58.317 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:03:58.551 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 3995 times
0:03:58.551 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:58.616 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 12 times
0:03:58.616 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:03:58.674 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times
0:03:58.674 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:03:58.734 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 8 times
0:03:58.734 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:03:58.801 352M / 6G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 0 times
0:03:58.801 352M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:03:58.912 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times
0:03:58.912 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:04:01.190 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 5 times
0:04:01.190 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:04:01.256 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2 times
0:04:01.256 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:04:01.326 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 26 times
0:04:01.326 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:04:01.389 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1 times
0:04:01.389 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:04:01.445 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times
0:04:01.445 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:04:01.508 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 0 times
0:04:01.508 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:04:01.508 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 0 times
0:04:01.508 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:04:01.615 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times
0:04:01.615 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 0 times
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:04:03.782 348M / 6G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times
0:04:03.782 348M / 6G INFO General (simplification.cpp : 309) Running Hidden EC remover (meta)
0:04:03.887 348M / 6G INFO General (simplification.cpp : 313) Disrupting self-conjugate edges
0:04:04.352 340M / 6G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:04:04.352 340M / 6G INFO General (simplification.cpp : 438) Removing isolated edges
0:04:04.415 340M / 6G INFO General (simplification.cpp : 461) Counting average coverage
0:04:04.687 340M / 6G INFO General (simplification.cpp : 467) Average coverage = 2.33533
0:04:04.687 340M / 6G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:04:04.687 340M / 6G INFO General (contig_output_stage.cpp : 40) Writing GFA to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/assembly_graph_with_scaffolds.gfa
0:04:06.603 340M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/before_rr.fasta
0:04:10.097 340M / 6G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/assembly_graph.fastg
0:04:18.002 340M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/simplified_contigs.fasta
0:04:20.211 340M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/final_contigs.fasta
0:04:22.392 340M / 6G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:04:22.392 340M / 6G INFO General (contig_output_stage.cpp : 40) Writing GFA to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/assembly_graph_with_scaffolds.gfa
0:04:24.127 340M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/before_rr.fasta
0:04:26.122 340M / 6G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/assembly_graph.fastg
0:04:32.371 340M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/simplified_contigs.fasta
0:04:34.470 340M / 6G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K33/final_contigs.fasta
0:04:36.670 340M / 6G INFO General (launch.hpp : 141) SPAdes finished
0:04:37.658 48M / 6G INFO General (main.cpp : 108) Assembling time: 0 hours 4 minutes 37 seconds
== Running assembler: K55
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/mda_mode.info
0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/meta_mode.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 256 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/master, git revision 33c36825c7e5dc2874918cad6c1a01a3197451c1
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/dataset.info) with K=55
0:00:00.000 4M / 4M INFO General (launch.hpp : 54) SPAdes started
0:00:00.000 4M / 4M INFO General (launch.hpp : 61) Starting from stage: construction
0:00:00.000 4M / 4M INFO General (launch.hpp : 64) Two-step RR enabled: 1
0:00:00.000 4M / 4M INFO General (launch.hpp : 82) Will need read mapping, kmer mapper will be attached
0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.016 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.017 4M / 4M INFO General (construction.cpp : 111) Max read length 150
0:00:00.017 4M / 4M INFO General (construction.cpp : 117) Average read length 149.998
0:00:00.017 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.019 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 144 files using 12 threads. This might take a while.
0:00:00.020 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:00:00.020 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.111 Gb
0:00:00.020 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 233016
0:00:09.859 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 4000000 reads
0:00:09.859 6G / 6G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:04:05.767 48M / 6G INFO General (kmer_splitters.hpp : 308) Used 4000000 reads
0:04:05.767 48M / 6G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:04:32.771 48M / 6G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 111671920 kmers in total.
0:04:32.771 48M / 6G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:04:43.912 48M / 6G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:04:43.913 48M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:04:43.913 48M / 6G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 192 files using 12 threads. This might take a while.
0:04:43.914 48M / 6G INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:04:43.915 48M / 6G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.10981 Gb
0:04:43.915 48M / 6G INFO General (kmer_splitters.hpp : 97) Using cell size of 174762
0:04:57.706 6G / 6G INFO General (kmer_splitters.hpp : 380) Processed 77062303 kmers
0:05:06.148 6G / 6G INFO General (kmer_splitters.hpp : 380) Processed 111671932 kmers
0:05:06.149 6G / 6G INFO General (kmer_splitters.hpp : 385) Used 111671932 kmers.
0:05:06.428 48M / 6G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:05:20.051 48M / 6G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 111782631 kmers in total.
0:05:20.051 48M / 6G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:05:29.339 48M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:05:37.581 68M / 6G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:05:41.861 68M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 51856088 bytes occupied (3.71121 bits per kmer).
0:05:42.032 176M / 6G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:05:55.481 176M / 6G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:05:58.169 176M / 6G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:06:00.127 176M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:06:18.377 296M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1175318 sequences extracted
0:06:26.884 296M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:06:33.212 296M / 6G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 1 loops collected
0:06:34.261 596M / 6G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:06:34.261 596M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:06:34.261 596M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:06:39.632 648M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 51788536 bytes occupied (3.71005 bits per kmer).
0:06:39.953 1G / 6G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:06:51.000 1G / 6G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:07:02.621 1G / 6G INFO General (construction.cpp : 464) Processed 2350627 edges
0:07:03.108 436M / 6G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:07:05.638 432M / 6G INFO ThresholdFinder (ec_threshold_finder.hpp : 114) Bucket size: 5
0:07:05.638 432M / 6G INFO ThresholdFinder (ec_threshold_finder.hpp : 129) Proper threshold was not found. Threshold set to 0.1 of average coverage
0:07:06.322 432M / 6G INFO General (genomic_info_filler.cpp : 98) Average edge coverage: 1.70138
0:07:06.322 432M / 6G INFO General (genomic_info_filler.cpp : 99) Graph threshold: 0.170138
0:07:06.322 432M / 6G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 0.170138
0:07:06.322 432M / 6G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:07:06.322 432M / 6G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:07:06.322 432M / 6G INFO General (graph_pack.hpp : 113) Index refill
0:07:06.323 432M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:07:06.323 432M / 6G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 192 files using 12 threads. This might take a while.
0:07:06.323 432M / 6G INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:07:06.323 432M / 6G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.09939 Gb
0:07:06.323 432M / 6G INFO General (kmer_splitters.hpp : 97) Using cell size of 174762
0:07:16.416 7G / 7G INFO General (edge_index_builders.hpp : 77) Processed 2350627 edges
0:07:16.416 7G / 7G INFO General (edge_index_builders.hpp : 82) Used 2350627 sequences.
0:07:16.622 432M / 7G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:07:23.601 432M / 7G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 111671920 kmers in total.
0:07:23.601 432M / 7G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:07:32.337 432M / 7G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:07:40.209 488M / 7G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:07:43.112 488M / 7G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 51790560 bytes occupied (3.71019 bits per kmer).
0:07:46.177 2G / 7G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:07:53.461 2G / 7G INFO General (edge_index.hpp : 92) Index refilled
0:07:53.463 2G / 7G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:07:57.577 3G / 7G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:07:59.255 3G / 7G INFO General (gap_closer.cpp : 138) Used 1000000 paired reads
0:07:59.255 3G / 7G INFO General (gap_closer.cpp : 140) Merging paired indices
0:08:01.201 3G / 7G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:08:07.170 3G / 7G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 737 gaps after checking 57965 candidates
0:08:07.621 2G / 7G INFO StageManager (stage.cpp : 132) STAGE == Preliminary Simplification
0:08:07.817 436M / 7G INFO General (simplification.cpp : 333) Graph simplification started
0:08:07.817 436M / 7G INFO General (simplification.cpp : 87) PROCEDURE == InitialCleaning
0:08:07.817 436M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:08:07.991 436M / 7G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 9 times
0:08:07.991 436M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:08:08.301 432M / 7G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 10326 times
0:08:08.301 432M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:08:15.006 460M / 7G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 255303 times
0:08:15.006 460M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:08:15.757 460M / 7G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 13144 times
0:08:15.757 460M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with low flanking coverage
0:08:16.681 464M / 7G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with low flanking coverage triggered 18943 times
0:08:16.783 456M / 7G INFO General (graph_simplification.hpp : 602) Creating parallel br instance
0:08:16.783 456M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 1
0:08:16.783 456M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:08:18.955 456M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 87766 times
0:08:18.955 456M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:08:31.809 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 38028 times
0:08:31.809 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:08:31.973 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 3 times
0:08:31.973 632M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 2
0:08:31.973 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:08:31.998 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 83 times
0:08:31.998 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:08:31.999 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:08:31.999 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:08:33.722 636M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 32284 times
0:08:33.722 636M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 3
0:08:33.722 636M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:08:33.758 636M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 133 times
0:08:33.759 636M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:08:33.764 636M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 5 times
0:08:33.764 636M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:08:33.833 636M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1038 times
0:08:33.833 636M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 4
0:08:33.833 636M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:08:33.909 636M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 8 times
0:08:33.909 636M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:08:33.990 636M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 2 times
0:08:33.990 636M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:08:34.071 628M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:08:34.071 628M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 5
0:08:34.071 628M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:08:34.071 628M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:08:34.071 628M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:08:34.071 628M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:08:34.071 628M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:08:34.071 628M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:08:34.071 628M / 7G INFO General (simplification.cpp : 378) PostSimplification disabled
0:08:34.071 628M / 7G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:08:34.071 628M / 7G INFO General (graph_pack.hpp : 113) Index refill
0:08:34.719 628M / 7G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:08:34.719 628M / 7G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 192 files using 12 threads. This might take a while.
0:08:34.798 628M / 7G INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:08:34.798 628M / 7G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.09408 Gb
0:08:34.798 628M / 7G INFO General (kmer_splitters.hpp : 97) Using cell size of 174762
0:08:39.571 7G / 7G INFO General (edge_index_builders.hpp : 77) Processed 414538 edges
0:08:39.571 7G / 7G INFO General (edge_index_builders.hpp : 82) Used 414538 sequences.
0:08:39.769 624M / 7G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:08:44.236 624M / 7G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 94691923 kmers in total.
0:08:44.236 624M / 7G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:08:49.640 624M / 7G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:08:58.931 680M / 7G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:09:01.304 680M / 7G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 43919336 bytes occupied (3.7105 bits per kmer).
0:09:04.120 2G / 7G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:09:09.846 2G / 7G INFO General (edge_index.hpp : 92) Index refilled
0:09:09.883 2G / 7G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:09:11.047 2G / 7G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:09:15.978 2G / 7G INFO General (gap_closer.cpp : 138) Used 1000000 paired reads
0:09:15.978 2G / 7G INFO General (gap_closer.cpp : 140) Merging paired indices
0:09:18.736 2G / 7G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:09:19.619 2G / 7G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 8 gaps after checking 5284 candidates
0:09:19.901 2G / 7G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:09:19.901 2G / 7G INFO General (simplification.cpp : 438) Removing isolated edges
0:09:20.545 2G / 7G INFO General (simplification.cpp : 461) Counting average coverage
0:09:20.856 2G / 7G INFO General (simplification.cpp : 467) Average coverage = 1.85271
0:09:20.856 2G / 7G INFO StageManager (stage.cpp : 132) STAGE == Preliminary Paired Information Counting
0:09:24.827 2G / 7G INFO General (graph_pack.hpp : 121) Normalizing k-mer map. Total 4314482 kmers to process
0:09:29.252 2G / 7G INFO General (graph_pack.hpp : 123) Normalizing done
0:09:29.252 2G / 7G INFO General (pair_info_count.cpp : 320) Min edge length for estimation: 900
0:09:29.252 2G / 7G INFO General (pair_info_count.cpp : 331) Estimating insert size for library #0
0:09:29.252 2G / 7G INFO General (pair_info_count.cpp : 190) Estimating insert size (takes a while)
0:09:29.388 3G / 7G INFO General (pair_info_count.cpp : 39) Selecting usual mapper
0:09:34.403 3G / 7G INFO General (sequence_mapper_notifier.h: 98) Total 1000000 reads processed
0:09:34.526 3G / 7G INFO General (pair_info_count.cpp : 209) Edge pairs: 67108864 (rough upper limit)
0:09:34.526 3G / 7G INFO General (pair_info_count.cpp : 213) 421437 paired reads (42.1437% of all) aligned to long edges
0:09:34.551 2G / 7G INFO General (pair_info_count.cpp : 354) Insert size = 248.661, deviation = 11.0111, left quantile = 234, right quantile = 263, read length = 150
0:09:34.666 3G / 7G INFO General (pair_info_count.cpp : 371) Filtering data for library #0
0:09:34.667 3G / 7G INFO General (pair_info_count.cpp : 39) Selecting usual mapper
0:09:39.408 3G / 7G INFO General (sequence_mapper_notifier.h: 98) Total 1000000 reads processed
0:09:39.408 3G / 7G INFO General (pair_info_count.cpp : 383) Mapping library #0
0:09:39.408 3G / 7G INFO General (pair_info_count.cpp : 385) Mapping paired reads (takes a while)
0:09:39.408 3G / 7G INFO General (pair_info_count.cpp : 289) Left insert size quantile 234, right insert size quantile 263, filtering threshold 1, rounding threshold 0
0:09:39.423 3G / 7G INFO General (pair_info_count.cpp : 39) Selecting usual mapper
0:09:43.995 3G / 7G INFO General (sequence_mapper_notifier.h: 98) Total 1000000 reads processed
0:09:44.109 2G / 7G INFO StageManager (stage.cpp : 132) STAGE == Preliminary Distance Estimation
0:09:44.109 2G / 7G INFO General (distance_estimation.cpp : 225) Processing library #0
0:09:44.109 2G / 7G INFO General (distance_estimation.cpp : 130) Weight Filter Done
0:09:44.109 2G / 7G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SIMPLE distance estimator
0:09:44.820 2G / 7G INFO General (distance_estimation.cpp : 35) Filtering info
0:09:44.820 2G / 7G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 413706
0:09:45.407 2G / 7G INFO General (pair_info_filters.hpp : 263) Done filtering
0:09:45.408 2G / 7G INFO General (distance_estimation.cpp : 172) Refining clustered pair information
0:09:45.599 2G / 7G INFO General (distance_estimation.cpp : 174) The refining of clustered pair information has been finished
0:09:45.599 2G / 7G INFO General (distance_estimation.cpp : 176) Improving paired information
0:09:46.357 2G / 7G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 466; contradictional = 0
0:09:47.159 2G / 7G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 5; contradictional = 0
0:09:47.159 2G / 7G INFO General (distance_estimation.cpp : 183) Filling scaffolding index
0:09:47.159 2G / 7G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SMOOTHING distance estimator
0:09:47.453 2G / 7G INFO General (distance_estimation.cpp : 35) Filtering info
0:09:47.453 2G / 7G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 405418
0:09:47.795 2G / 7G INFO General (pair_info_filters.hpp : 263) Done filtering
0:09:47.796 2G / 7G INFO General (distance_estimation.cpp : 230) Clearing raw paired index
0:09:47.939 2G / 7G INFO StageManager (stage.cpp : 132) STAGE == Preliminary Repeat Resolving
0:09:47.939 2G / 7G INFO General (repeat_resolving.cpp : 56) Setting up preliminary path extend settings
0:09:47.939 2G / 7G INFO General (repeat_resolving.cpp : 69) Using Path-Extend repeat resolving
0:09:47.939 2G / 7G INFO General (launcher.cpp : 558) ExSPAnder repeat resolving tool started
0:09:50.782 3G / 7G INFO General (launcher.cpp : 419) Creating main extenders, unique edge length = 2000
0:09:51.208 3G / 7G INFO General (extenders_logic.cpp : 489) Using 1 paired-end library
0:09:51.208 3G / 7G INFO General (extenders_logic.cpp : 490) Using 1 paired-end scaffolding library
0:09:51.208 3G / 7G INFO General (extenders_logic.cpp : 491) Using 0 single read libraries
0:09:51.208 3G / 7G INFO General (launcher.cpp : 438) Will not use read cloud path extend in this mode
0:09:51.208 3G / 7G INFO General (launcher.cpp : 458) Total number of extenders is 3
0:09:51.208 3G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 0 paths from 202267 (0%)
0:09:51.218 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 128 paths from 202267 (0%)
0:09:51.229 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 256 paths from 202267 (0%)
0:09:51.247 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 512 paths from 202267 (0%)
0:09:51.278 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 1024 paths from 202267 (0%)
0:09:51.338 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 2048 paths from 202267 (1%)
0:09:51.458 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 4096 paths from 202267 (2%)
0:09:51.687 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 8192 paths from 202267 (4%)
0:09:52.154 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 16384 paths from 202267 (8%)
0:09:52.367 3G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 20227 paths from 202267 (10%)
0:09:53.126 3G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 32768 paths from 202267 (16%)
0:09:53.555 4G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 40454 paths from 202267 (20%)
0:09:54.731 4G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 60681 paths from 202267 (30%)
0:09:55.007 4G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 65536 paths from 202267 (32%)
0:09:55.937 4G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 80908 paths from 202267 (40%)
0:09:57.123 4G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 101135 paths from 202267 (50%)
0:09:58.337 4G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 121362 paths from 202267 (60%)
0:09:58.845 4G / 7G INFO CompositeExtender (path_extender.hpp : 887) Processed 131072 paths from 202267 (64%)
0:09:59.407 4G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 141589 paths from 202267 (70%)
0:10:00.465 5G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 161816 paths from 202267 (80%)
0:10:01.540 5G / 7G INFO CompositeExtender (path_extender.hpp : 889) Processed 182043 paths from 202267 (90%)
0:10:02.750 5G / 7G INFO General (launcher.cpp : 247) Finalizing paths
0:10:02.750 5G / 7G INFO General (launcher.cpp : 249) Deduplicating paths
0:10:03.846 5G / 7G INFO General (launcher.cpp : 253) Paths deduplicated
0:10:03.846 5G / 7G INFO General (launcher.cpp : 260) Overlaps will not be removed
0:10:05.633 5G / 7G INFO General (launcher.cpp : 270) Paths finalized
0:10:05.633 5G / 7G INFO General (launcher.cpp : 465) Closing gaps in paths
0:10:05.634 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 128 paths from 200859 (0%)
0:10:05.635 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 256 paths from 200859 (0%)
0:10:05.637 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 512 paths from 200859 (0%)
0:10:05.640 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 1024 paths from 200859 (0%)
0:10:05.647 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 2048 paths from 200859 (1%)
0:10:05.663 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 4096 paths from 200859 (2%)
0:10:05.693 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 8192 paths from 200859 (4%)
0:10:05.754 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 16384 paths from 200859 (8%)
0:10:05.879 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 32768 paths from 200859 (16%)
0:10:06.132 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 65536 paths from 200859 (32%)
0:10:06.643 5G / 7G INFO PathPolisher (path_polisher.cpp : 30) Processed 131072 paths from 200859 (65%)
0:10:08.220 5G / 7G INFO General (launcher.cpp : 535) Gap closing completed
0:10:09.024 5G / 7G INFO General (launcher.cpp : 247) Finalizing paths
0:10:09.024 5G / 7G INFO General (launcher.cpp : 249) Deduplicating paths
0:10:09.413 5G / 7G INFO General (launcher.cpp : 253) Paths deduplicated
0:10:09.413 5G / 7G INFO General (launcher.cpp : 260) Overlaps will not be removed
0:10:10.898 5G / 7G INFO General (launcher.cpp : 270) Paths finalized
0:10:11.981 5G / 7G INFO General (launcher.cpp : 645) ExSPAnder repeat resolving tool finished
0:10:13.864 4G / 7G INFO General (repeat_resolving.cpp : 75) Restoring initial path extend settings
0:10:13.864 4G / 7G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:10:13.864 4G / 7G INFO General (contig_output_stage.cpp : 40) Writing GFA to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/assembly_graph_with_scaffolds.gfa
0:10:15.839 4G / 7G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/before_rr.fasta
0:10:19.019 4G / 7G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/assembly_graph.fastg
0:10:28.977 4G / 7G INFO General (contig_output_stage.cpp : 20) Outputting FastG paths to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/final_contigs.paths
0:10:34.183 4G / 7G INFO General (contig_output_stage.cpp : 20) Outputting FastG paths to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/scaffolds.paths
0:10:38.983 4G / 7G INFO StageManager (stage.cpp : 132) STAGE == Second Phase Setup
0:10:38.983 4G / 7G INFO General (second_phase_setup.cpp : 20) Preparing second phase
0:10:40.355 2G / 7G INFO General (second_phase_setup.cpp : 28) Moving preliminary contigs from /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/final_contigs.fasta to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/first_pe_contigs.fasta
0:10:40.356 2G / 7G INFO General (second_phase_setup.cpp : 40) Ready to run second phase
0:10:40.356 2G / 7G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:10:40.555 632M / 7G INFO General (simplification.cpp : 333) Graph simplification started
0:10:40.555 632M / 7G INFO General (simplification.cpp : 87) PROCEDURE == InitialCleaning
0:10:40.555 632M / 7G INFO General (simplification.cpp : 57) Most init cleaning disabled on main iteration
0:10:40.555 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:10:40.611 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:10:40.611 632M / 7G INFO General (graph_simplification.hpp : 602) Creating parallel br instance
0:10:40.611 632M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 1
0:10:40.611 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:10:40.683 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:10:40.683 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:10:41.182 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 641 times
0:10:41.182 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:10:41.258 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:10:41.258 632M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 2
0:10:41.259 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:10:41.259 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2 times
0:10:41.259 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:10:41.259 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:10:41.260 632M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 3
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:10:41.260 632M / 7G INFO General (simplification.cpp : 339) PROCEDURE == Simplification cycle, iteration 4
0:10:41.260 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:10:41.341 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:10:41.341 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:10:41.419 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:10:41.419 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:10:41.495 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:10:41.495 632M / 7G INFO General (simplification.cpp : 174) PROCEDURE == Post simplification
0:10:41.496 632M / 7G INFO General (graph_simplification.hpp : 602) Creating parallel br instance
0:10:41.496 632M / 7G INFO General (graph_simplification.hpp : 602) Creating parallel br instance
0:10:41.496 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:10:41.568 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 16 times
0:10:41.568 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:10:41.642 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 2 times
0:10:41.642 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:10:41.769 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times
0:10:41.769 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:10:44.261 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 30 times
0:10:44.261 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:10:44.336 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:10:44.336 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:10:44.414 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 95 times
0:10:44.414 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:10:44.480 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:10:44.480 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Final bulge remover
0:10:44.559 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Final bulge remover triggered 9 times
0:10:44.559 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:10:44.617 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times
0:10:44.617 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:10:44.681 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 0 times
0:10:44.682 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:10:44.750 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 0 times
0:10:44.750 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:10:44.872 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times
0:10:44.872 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:10:47.559 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 0 times
0:10:47.559 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:10:47.641 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:10:47.641 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:10:47.718 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 1 times
0:10:47.718 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:10:47.788 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:10:47.788 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Final bulge remover
0:10:47.859 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Final bulge remover triggered 0 times
0:10:47.859 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:10:47.921 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times
0:10:47.921 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover
0:10:47.992 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 0 times
0:10:47.992 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage
0:10:47.992 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 0 times
0:10:47.992 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper
0:10:48.118 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times
0:10:48.118 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 0 times
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Final bulge remover
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Final bulge remover triggered 0 times
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta)
0:10:50.523 632M / 7G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times
0:10:50.523 632M / 7G INFO General (simplification.cpp : 309) Running Hidden EC remover (meta)
0:10:50.615 632M / 7G INFO General (simplification.cpp : 313) Disrupting self-conjugate edges
0:10:51.125 632M / 7G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:10:51.125 632M / 7G INFO General (contig_output_stage.cpp : 40) Writing GFA to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/assembly_graph_with_scaffolds.gfa
0:10:52.900 632M / 7G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/before_rr.fasta
0:10:54.977 632M / 7G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/assembly_graph.fastg
0:11:01.245 632M / 7G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/simplified_contigs.fasta
0:11:03.349 632M / 7G INFO General (contig_output.hpp : 22) Outputting contigs to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1//K55/intermediate_contigs.fasta
0:11:05.456 632M / 7G INFO StageManager (stage.cpp : 132) STAGE == Barcode map construction
0:11:05.456 632M / 7G INFO BarcodeMapConstrusctionS (barcode_index_construction: 19) Barcode index construction started...
0:11:05.456 632M / 7G INFO General (graph_pack.hpp : 113) Index refill
0:11:05.457 632M / 7G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:11:05.457 632M / 7G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 192 files using 12 threads. This might take a while.
0:11:05.458 632M / 7G INFO General (file_limit.hpp : 32) Open file limit set to 1024
0:11:05.458 632M / 7G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 7.09397 Gb
0:11:05.458 632M / 7G INFO General (kmer_splitters.hpp : 97) Using cell size of 174762
0:11:09.979 7G / 7G INFO General (edge_index_builders.hpp : 77) Processed 400624 edges
0:11:09.979 7G / 7G INFO General (edge_index_builders.hpp : 82) Used 400624 sequences.
0:11:10.190 632M / 7G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:11:17.303 632M / 7G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 94133052 kmers in total.
0:11:17.303 632M / 7G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:11:23.123 632M / 7G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:11:31.043 684M / 7G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:11:34.763 684M / 7G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 43657640 bytes occupied (3.71029 bits per kmer).
0:11:37.291 2G / 7G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:11:43.065 2G / 7G INFO General (edge_index.hpp : 92) Index refilled
0:11:43.065 2G / 7G INFO General (graph_pack.hpp : 121) Normalizing k-mer map. Total 4456080 kmers to process
0:11:48.325 2G / 7G INFO General (graph_pack.hpp : 123) Normalizing done
0:11:48.873 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 123) Starting barcode index construction from 10X reads
0:11:48.886 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 128 reads.
0:11:48.893 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 256 reads.
0:11:48.901 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 512 reads.
0:11:48.917 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 1024 reads.
0:11:48.946 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 2048 reads.
0:11:49.007 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 4096 reads.
0:11:49.135 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 8192 reads.
0:11:49.383 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 16384 reads.
0:11:49.893 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 32768 reads.
0:11:50.928 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 65536 reads.
0:11:52.960 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 131072 reads.
0:11:57.296 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 262144 reads.
0:12:05.586 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 524288 reads.
0:12:23.171 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 147) Processed 1048576 reads.
0:13:04.052 2G / 7G INFO BarcodeMapperBuilder (barcode_index_builder.hpp : 151) FillMap finished
0:13:04.053 2G / 7G INFO BarcodeMapConstrusctionS (barcode_index_construction: 40) Barcode index construction finished.
0:13:04.314 2G / 7G INFO BarcodeMapConstrusctionS (barcode_index_construction: 42) Average barcode coverage: 4.429374
0:13:04.550 2G / 7G INFO General (distribution_extractor_hel: 60) Estimated training length: 10960
0:13:04.550 2G / 7G INFO ClusterDistributionExtra (distribution_extractor_hel: 199) Extracting read cloud cluster statistics
0:13:06.769 2G / 7G INFO ClusterDistributionExtra (distribution_extractor_hel: 281) Estimated fragment length median: 18316
0:13:06.769 2G / 7G INFO ClusterDistributionExtra (distribution_extractor_hel: 222) Estimated gap within cluster: 10000
0:13:06.769 2G / 7G INFO ClusterDistributionExtra (distribution_extractor_hel: 224) Estimated mean cluster length: 18316
0:13:06.769 2G / 7G INFO ClusterDistributionExtra (distribution_extractor_hel: 225) Estimated median cluster length: 18501
0:13:06.769 2G / 7G INFO ClusterDistributionExtra (distribution_extractor_hel: 226) Estimated median cluster coverage: 0.0107021
0:13:07.055 2G / 7G INFO StageManager (stage.cpp : 132) STAGE == Paired Information Counting
0:13:11.297 3G / 7G INFO General (graph_pack.hpp : 121) Normalizing k-mer map. Total 4456080 kmers to process
0:13:11.297 3G / 7G INFO General (graph_pack.hpp : 123) Normalizing done
0:13:11.297 3G / 7G INFO General (pair_info_count.cpp : 320) Min edge length for estimation: 900
0:13:11.297 3G / 7G INFO General (pair_info_count.cpp : 331) Estimating insert size for library #0
0:13:11.297 3G / 7G INFO General (pair_info_count.cpp : 190) Estimating insert size (takes a while)
0:13:11.457 3G / 7G INFO General (pair_info_count.cpp : 39) Selecting usual mapper
0:13:16.515 3G / 7G INFO General (sequence_mapper_notifier.h: 98) Total 1000000 reads processed
0:13:16.638 3G / 7G INFO General (pair_info_count.cpp : 209) Edge pairs: 67108864 (rough upper limit)
0:13:16.638 3G / 7G INFO General (pair_info_count.cpp : 213) 424986 paired reads (42.4986% of all) aligned to long edges
0:13:16.673 3G / 7G INFO General (pair_info_count.cpp : 354) Insert size = 248.664, deviation = 11.0107, left quantile = 234, right quantile = 263, read length = 150
0:13:16.796 3G / 7G INFO General (pair_info_count.cpp : 371) Filtering data for library #0
0:13:16.797 3G / 7G INFO General (pair_info_count.cpp : 39) Selecting usual mapper
0:13:21.494 3G / 7G INFO General (sequence_mapper_notifier.h: 98) Total 1000000 reads processed
0:13:21.494 3G / 7G INFO General (pair_info_count.cpp : 383) Mapping library #0
0:13:21.495 3G / 7G INFO General (pair_info_count.cpp : 385) Mapping paired reads (takes a while)
0:13:21.495 3G / 7G INFO General (pair_info_count.cpp : 289) Left insert size quantile 234, right insert size quantile 263, filtering threshold 1, rounding threshold 0
0:13:21.510 3G / 7G INFO General (pair_info_count.cpp : 39) Selecting usual mapper
0:13:26.180 3G / 7G INFO General (sequence_mapper_notifier.h: 98) Total 1000000 reads processed
0:13:26.299 3G / 7G INFO General (pair_info_count.cpp : 327) Mapping contigs library #1
0:13:26.299 3G / 7G INFO General (pair_info_count.cpp : 39) Selecting usual mapper
0:13:34.913 3G / 7G INFO General (sequence_mapper_notifier.h: 80) Processed 200000 reads
0:13:35.188 3G / 7G INFO General (sequence_mapper_notifier.h: 98) Total 200868 reads processed
0:13:35.189 3G / 7G INFO StageManager (stage.cpp : 132) STAGE == Distance Estimation
0:13:35.189 3G / 7G INFO General (distance_estimation.cpp : 225) Processing library #0
0:13:35.189 3G / 7G INFO General (distance_estimation.cpp : 130) Weight Filter Done
0:13:35.189 3G / 7G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SIMPLE distance estimator
0:13:35.964 3G / 7G INFO General (distance_estimation.cpp : 35) Filtering info
0:13:35.964 3G / 7G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 404041
0:13:36.615 3G / 7G INFO General (pair_info_filters.hpp : 263) Done filtering
0:13:36.616 3G / 7G INFO General (distance_estimation.cpp : 172) Refining clustered pair information
0:13:36.784 3G / 7G INFO General (distance_estimation.cpp : 174) The refining of clustered pair information has been finished
0:13:36.784 3G / 7G INFO General (distance_estimation.cpp : 176) Improving paired information
0:13:37.596 3G / 7G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 229; contradictional = 0
0:13:38.364 3G / 7G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 2; contradictional = 0
0:13:38.364 3G / 7G INFO General (distance_estimation.cpp : 183) Filling scaffolding index
0:13:38.364 3G / 7G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SMOOTHING distance estimator
0:13:38.618 3G / 7G INFO General (distance_estimation.cpp : 35) Filtering info
0:13:38.618 3G / 7G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 400900
0:13:39.086 3G / 7G INFO General (pair_info_filters.hpp : 263) Done filtering
0:13:39.087 3G / 7G INFO General (distance_estimation.cpp : 230) Clearing raw paired index
0:13:39.214 3G / 7G INFO StageManager (stage.cpp : 132) STAGE == Scaffold graph construction
0:13:39.214 3G / 7G INFO ScaffoldGraphConstructio (scaffold_graph_constructio: 86) Scaffold graph construction started
0:13:39.214 3G / 7G INFO ScaffoldGraphConstructio (scaffold_graph_constructio: 89) 190 clusters loaded
0:13:39.214 3G / 7G INFO ScaffoldGraphConstructio (scaffold_graph_constructio: 96) Length upper bound: 18501
0:13:39.678 3G / 7G INFO ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 56) With length cutoff: 18501, median long edge coverage: 6.27287, and maximal unique coverage: 50
0:13:39.678 3G / 7G INFO ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 57) Unique edges quantity: 106, unique edges length 2613746, total edges length 188266124
0:13:39.678 3G / 7G WARN ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 59) Less than half of genome in unique edges!
0:13:39.678 3G / 7G INFO CloudScaffoldGraphConstr (scaffold_graph_storage_con: 173) Constructing scaffold graph in basic mode
0:13:39.678 3G / 7G INFO General (scaffold_graph_constructio: 145) Constructing scaffold graph with length threshold 18501
0:13:39.678 3G / 7G INFO General (scaffold_graph_constructio: 83) Max training gap: 19501
0:13:39.678 3G / 7G INFO General (scaffold_graph_constructio: 84) Min training length: 56503
0:13:39.680 3G / 7G INFO General (scaffold_graph_constructio: 157) Created 4 stages
0:13:39.680 3G / 7G INFO General (scaffold_graph_constructio: 98) Constructing initial scaffold graph
0:13:39.680 3G / 7G INFO UniqueScaffoldGraphConst (scaffold_graph_constructor: 174) Scaffolding distance: 19501
0:13:39.680 3G / 7G INFO General (scaffold_graph_constructio: 100) Constructed initial graph
0:13:39.680 3G / 7G INFO General (scaffold_graph_constructio: 102) 106 vertices and 8 edges in initial graph
0:13:39.680 3G / 7G INFO General (scaffold_graph_constructio: 105) Starting Long edge score filter
0:13:39.905 3G / 7G INFO LabeledDistributionThres (containment_index_threshol: 157) 2 training edges.
0:13:39.905 3G / 7G INFO LongEdgeScoreHistogramCo (containment_index_threshol: 75) 22 score samples
0:13:39.905 3G / 7G INFO LabeledDistributionThres (containment_index_threshol: 174) Estimated score threshold: 0
0:13:39.905 3G / 7G WARN General (construction_callers.cpp : 71) Estimated score threshold 0 is too small, setting 0.001 as default threshold
== Error == system call for: "['/ebio/abt3_projects/software/dev/haptag-mg/data_sim/bin/scripts/spades/bin/spades-core', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/config.info', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/mda_mode.info', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/meta_mode.info']" finished abnormally, err code: -8
======= SPAdes pipeline finished abnormally and WITH WARNINGS!
=== Error correction and assembling warnings:
* 0:13:39.678 3G / 7G WARN ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 59) Less than half of genome in unique edges!
* 0:13:39.905 3G / 7G WARN General (construction_callers.cpp : 71) Estimated score threshold 0 is too small, setting 0.001 as default threshold
======= Warnings saved to /ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/warnings.log
=== ERRORs:
* system call for: "['/ebio/abt3_projects/software/dev/haptag-mg/data_sim/bin/scripts/spades/bin/spades-core', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/config.info', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/mda_mode.info', '/ebio/abt3_scratch/haptag-mg_49025743982/athena/megahit/1/3/4000000/sim_reads/1/K55/configs/meta_mode.info']" finished abnormally, err code: -8
In case you have troubles running SPAdes, you can write to [email protected]
or report an issue on our GitHub repository github.com/ablab/spades
Please provide us with params.txt and spades.log files from the output directory.
My environment
Ubuntu 18.04.4
# Name Version Build Channel
_libgcc_mutex 0.1 conda_forge conda-forge
_openmp_mutex 4.5 0_gnu conda-forge
athena_meta 1.3 py_1 bioconda
backports 1.0 py_2 conda-forge
backports.shutil_get_terminal_size 1.0.0 py_3 conda-forge
backports_abc 0.5 py_1 conda-forge
bwa 0.7.17 hed695b0_7 bioconda
bx-python 0.8.9 py27h213ead4_1 bioconda
bzip2 1.0.8 h516909a_2 conda-forge
ca-certificates 2020.6.20 hecda079_0 conda-forge
certifi 2019.11.28 py27h8c360ce_1 conda-forge
configparser 3.7.3 py27h8c360ce_2 conda-forge
curl 7.71.1 he644dc0_3 conda-forge
decorator 4.4.2 py_0 conda-forge
entrypoints 0.3 py27h8c360ce_1001 conda-forge
enum34 1.1.10 py27h8c360ce_1 conda-forge
flye 2.3.1 py27_0 bioconda
futures 3.3.0 py27h8c360ce_1 conda-forge
htslib 1.9 ha228f0b_7 bioconda
idba_subasm 1.1.3a1 py27pl526hf484d3e_0 bioconda
ipykernel 4.10.0 py27_1 conda-forge
ipyparallel 6.2.4 py27h8c360ce_0 conda-forge
ipython 5.8.0 py27_1 conda-forge
ipython-cluster-helper 0.6.4 py_0 bioconda
ipython_genutils 0.2.0 py_1 conda-forge
jupyter_client 5.3.4 py27_1 conda-forge
jupyter_core 4.6.3 py27h8c360ce_1 conda-forge
krb5 1.17.1 hfafb76e_1 conda-forge
ld_impl_linux-64 2.34 h53a641e_7 conda-forge
libblas 3.8.0 17_openblas conda-forge
libcblas 3.8.0 17_openblas conda-forge
libcurl 7.71.1 hcdd3856_3 conda-forge
libdeflate 1.0 h14c3975_1 bioconda
libedit 3.1.20191231 h46ee950_1 conda-forge
libffi 3.2.1 he1b5a44_1007 conda-forge
libgcc 7.2.0 h69d50b8_2 conda-forge
libgcc-ng 9.2.0 h24d8f2e_2 conda-forge
libgfortran-ng 7.5.0 hdf63c60_6 conda-forge
libgomp 9.2.0 h24d8f2e_2 conda-forge
liblapack 3.8.0 17_openblas conda-forge
libopenblas 0.3.10 pthreads_hb3c22a3_3 conda-forge
libsodium 1.0.17 h516909a_0 conda-forge
libssh2 1.9.0 hab1572f_4 conda-forge
libstdcxx-ng 9.2.0 hdf63c60_2 conda-forge
lzo 2.10 h14c3975_1000 conda-forge
ncurses 6.1 hf484d3e_1002 conda-forge
netifaces 0.10.4 py27_1 bioconda
numpy 1.11.3 py27he5ce36f_1207 conda-forge
openssl 1.1.1g h516909a_0 conda-forge
pathlib2 2.3.5 py27h8c360ce_1 conda-forge
perl 5.26.2 h516909a_1006 conda-forge
pexpect 4.8.0 py27h8c360ce_1 conda-forge
pickleshare 0.7.5 py27h8c360ce_1001 conda-forge
pigz 2.3.4 hed695b0_1 conda-forge
pip 20.1.1 pyh9f0ad1d_0 conda-forge
prompt_toolkit 1.0.15 py_1 conda-forge
ptyprocess 0.6.0 py_1001 conda-forge
pygments 2.5.2 py_0 conda-forge
pysam 0.15.3 py27hda2845c_1 bioconda
python 2.7.15 h5a48372_1011_cpython conda-forge
python-dateutil 2.8.1 py_0 conda-forge
python-lzo 1.12 py27h42e1302_1001 conda-forge
python_abi 2.7 1_cp27mu conda-forge
pyzmq 19.0.0 py27h76efe43_1 conda-forge
readline 8.0 h46ee950_1 conda-forge
samtools 1.9 h10a08f8_12 bioconda
scandir 1.10.0 py27hdf8410d_1 conda-forge
setuptools 44.0.0 py27_0 conda-forge
simplegeneric 0.8.1 py_1 conda-forge
singledispatch 3.4.0.3 py27_1000 conda-forge
six 1.15.0 pyh9f0ad1d_0 conda-forge
sqlite 3.32.3 hcee41ef_1 conda-forge
tk 8.6.10 hed695b0_0 conda-forge
tornado 5.1.1 py27h14c3975_1000 conda-forge
traitlets 4.3.3 py27h8c360ce_1 conda-forge
wcwidth 0.2.5 pyh9f0ad1d_0 conda-forge
wheel 0.34.2 py_1 conda-forge
xz 5.2.5 h516909a_1 conda-forge
zeromq 4.3.2 he1b5a44_2 conda-forge
zlib 1.2.11 h516909a_1006 conda-forge
Pinging this, and a broader question: is cloudSPAdes not really being supported, given that it's been left as a pre-release since last May (https://github.com/ablab/spades/releases/tag/cloudspades-paper)? If so, then I'll just close this issue and focus on other assemblers.
@nick-youngblut cloudSPAdes is planned to be a part of SPAdes release eventually. The problem is standard: paper & conferences deadlines made it so that cloudSPAdes codebase diverged a lot from SPAdes mainline. This takes time, sadly.
@Itolstoganov will you please follow on this issue?
@asl thanks for the update! That helps a lot with understanding the current status of cloudSPAdes.
Hello @nick-youngblut, Unfortunately, I was not able to reproduce this error on a similar simulated dataset.
Could you please provide the reads that you used or more specific instructions on how to obtain them?
Thank you!
The reads were simulated via MGSIM. They can be obtained from: https://drive.google.com/drive/folders/1tbMIGCUNR2eoSOBK6W9IC6EEvX-jWo6R?usp=sharing
The commands used:
# tmp dir
TMPDIR="cloudmetaspades_tmp"
rm -rf $TMPDIR && mkdir -p $TMPDIR
# output dir
OUTDIR=`dirname cloudmetaspades/contigs.fasta`
rm -rf $OUTDIR
# formatting reads
gunzip -c R1.fq.gz | perl -pe 's/_BX:Z:/ BX:Z:/ if /^@/' > R1_cloud.fq
gunzip -c R1.fq.gz | perl -pe 's/_BX:Z:/ BX:Z:/ if /^@/' > R2_cloud.fq
# spades run
./bin/spades.py --meta -k auto --only-assembler -t 12 -m 252 \
--tmp-dir $TMPDIR -o $OUTDIR --gemcode1-1 R1_cloud.fq --gemcode1-2 R2_cloud.fq
Log for the run: cloudspades.log
@Itolstoganov were you table to access the files? I'd like to remove them from my account if you have already downloaded them.