Mercurial > repos > jpayne > seqsero_v2
view output/data_log.txt @ 15:1d6702e0bffd
Uploaded
| author | estrain |
|---|---|
| date | Wed, 01 Mar 2023 13:20:59 -0500 |
| parents | fae43708974d |
| children |
line wrap: on
line source
/bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found /bin/sh: 1: bwa: not found Command line: /root/miniconda3/envs/seqsero/bin/spades.py --careful --pe1-s /under-test/output/forward.fastq.gz_combined.fq --pe1-1 /under-test/output/forward.fastq.gz_mapped.fq --pe1-2 /under-test/output/reverse.fastq.gz_mapped.fq -t 1 -o /under-test/output/2018_11_08_19_41_18_temp System information: SPAdes version: 3.12.0 Python version: 2.7.13 OS: Linux-4.9.87-linuxkit-aufs-x86_64-with-debian-stretch-sid Output dir: /under-test/output/2018_11_08_19_41_18_temp Mode: read error correction and assembling Debug mode is turned OFF Dataset parameters: Multi-cell mode (you should set '--sc' flag if input data was obtained with MDA (single-cell) technology or --meta flag if processing metagenomic dataset) Reads: Library number: 1, library type: paired-end orientation: fr left reads: ['/under-test/output/forward.fastq.gz_mapped.fq'] right reads: ['/under-test/output/reverse.fastq.gz_mapped.fq'] interlaced reads: not specified single reads: ['/under-test/output/forward.fastq.gz_combined.fq'] merged reads: not specified Read error correction parameters: Iterations: 1 PHRED offset will be auto-detected Corrected reads will be compressed Assembly parameters: k: automatic selection based on read length Repeat resolution is enabled Mismatch careful mode is turned ON MismatchCorrector will be used Coverage cutoff is turned OFF Other parameters: Dir for temp files: /under-test/output/2018_11_08_19_41_18_temp/tmp Threads: 1 Memory limit (in Gb): 1 ======= SPAdes pipeline started. Log can be found here: /under-test/output/2018_11_08_19_41_18_temp/spades.log ===== Read error correction started. == Running read error correction tool: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-hammer /under-test/output/2018_11_08_19_41_18_temp/corrected/configs/config.info 0:00:00.002 4M / 4M INFO General (main.cpp : 75) Starting BayesHammer, built from N/A, git revision N/A 0:00:00.002 4M / 4M INFO General (main.cpp : 76) Loading config from /under-test/output/2018_11_08_19_41_18_temp/corrected/configs/config.info 0:00:00.013 4M / 4M INFO General (main.cpp : 78) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.013 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1 Gb 0:00:00.013 4M / 4M INFO General (main.cpp : 86) Trying to determine PHRED offset 0:00:00.016 4M / 4M INFO General (main.cpp : 92) Determined value is 33 0:00:00.016 4M / 4M INFO General (hammer_tools.cpp : 36) Hamming graph threshold tau=1, k=21, subkmer positions = [ 0 10 ] 0:00:00.016 4M / 4M INFO General (main.cpp : 113) Size of aux. kmer data 24 bytes === ITERATION 0 begins === 0:00:00.025 4M / 4M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.025 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:00.028 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.028 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.028 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 2785280 0:00:00.028 388M / 412M INFO K-mer Splitting (kmer_data.cpp : 97) Processing /under-test/output/forward.fastq.gz_mapped.fq 0:00:00.214 388M / 412M INFO K-mer Splitting (kmer_data.cpp : 97) Processing /under-test/output/reverse.fastq.gz_mapped.fq 0:00:00.395 388M / 412M INFO K-mer Splitting (kmer_data.cpp : 97) Processing /under-test/output/forward.fastq.gz_combined.fq 0:00:00.668 388M / 412M INFO K-mer Splitting (kmer_data.cpp : 112) Total 4925 reads processed 0:00:00.670 4M / 412M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.966 4M / 412M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 111540 kmers in total. 0:00:00.966 4M / 412M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:01.101 4M / 412M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.279 4M / 412M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:01.338 4M / 412M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 60488 bytes occupied (4.33839 bits per kmer). 0:00:01.342 4M / 412M INFO K-mer Counting (kmer_data.cpp : 356) Arranging kmers in hash map order 0:00:01.374 4M / 412M INFO General (main.cpp : 148) Clustering Hamming graph. 0:00:01.752 4M / 412M INFO General (main.cpp : 155) Extracting clusters 0:00:01.806 4M / 412M INFO General (main.cpp : 167) Clustering done. Total clusters: 76148 0:00:01.807 4M / 412M INFO K-mer Counting (kmer_data.cpp : 376) Collecting K-mer information, this takes a while. 0:00:01.808 4M / 412M INFO K-mer Counting (kmer_data.cpp : 382) Processing /under-test/output/forward.fastq.gz_mapped.fq 0:00:01.957 4M / 412M INFO K-mer Counting (kmer_data.cpp : 382) Processing /under-test/output/reverse.fastq.gz_mapped.fq 0:00:02.111 4M / 412M INFO K-mer Counting (kmer_data.cpp : 382) Processing /under-test/output/forward.fastq.gz_combined.fq 0:00:02.398 4M / 412M INFO K-mer Counting (kmer_data.cpp : 389) Collection done, postprocessing. 0:00:02.398 4M / 412M INFO K-mer Counting (kmer_data.cpp : 403) There are 111540 kmers in total. Among them 11174 (10.0179%) are singletons. 0:00:02.398 4M / 412M INFO General (main.cpp : 173) Subclustering Hamming graph 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 649) Subclustering done. Total 0 non-read kmers were generated. 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 650) Subclustering statistics: 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 651) Total singleton hamming clusters: 63364. Among them 39970 (63.08%) are good 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 652) Total singleton subclusters: 0. Among them 0 (-nan%) are good 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 653) Total non-singleton subcluster centers: 12784. Among them 10340 (80.8824%) are good 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 654) Average size of non-trivial subcluster: 3.76846 kmers 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 655) Average number of sub-clusters per non-singleton cluster: 1 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 656) Total solid k-mers: 50310 0:00:02.472 4M / 412M INFO Hamming Subclustering (kmer_cluster.cpp : 657) Substitution probabilities: [4,4]((0.945174,0.0222622,0.014199,0.0183649),(0.0223025,0.954287,0.0067997,0.016611),(0.0153556,0.00650769,0.953652,0.0244852),(0.0178668,0.0132381,0.0206468,0.948248)) 0:00:02.473 4M / 412M INFO General (main.cpp : 178) Finished clustering. 0:00:02.474 4M / 412M INFO General (main.cpp : 197) Starting solid k-mers expansion in 1 threads. 0:00:02.616 8M / 412M INFO General (main.cpp : 218) Solid k-mers iteration 0 produced 195 new k-mers. 0:00:02.761 8M / 412M INFO General (main.cpp : 218) Solid k-mers iteration 1 produced 0 new k-mers. 0:00:02.761 8M / 412M INFO General (main.cpp : 222) Solid k-mers finalized 0:00:02.761 8M / 412M INFO General (hammer_tools.cpp : 220) Starting read correction in 1 threads. 0:00:02.761 8M / 412M INFO General (hammer_tools.cpp : 233) Correcting pair of reads: /under-test/output/forward.fastq.gz_mapped.fq and /under-test/output/reverse.fastq.gz_mapped.fq 0:00:02.785 16M / 412M INFO General (hammer_tools.cpp : 168) Prepared batch 0 of 1192 reads. 0:00:02.868 16M / 412M INFO General (hammer_tools.cpp : 175) Processed batch 0 0:00:02.945 16M / 412M INFO General (hammer_tools.cpp : 185) Written batch 0 0:00:02.954 8M / 412M INFO General (hammer_tools.cpp : 264) Correcting single reads: /under-test/output/forward.fastq.gz_combined.fq 0:00:02.976 12M / 412M INFO General (hammer_tools.cpp : 127) Prepared batch 0 of 2541 reads. 0:00:03.074 12M / 412M INFO General (hammer_tools.cpp : 132) Processed batch 0 0:00:03.124 12M / 412M INFO General (hammer_tools.cpp : 136) Written batch 0 0:00:03.129 8M / 412M INFO General (hammer_tools.cpp : 274) Correction done. Changed 3954 bases in 1087 reads. 0:00:03.129 8M / 412M INFO General (hammer_tools.cpp : 275) Failed to correct 652 bases out of 974754. 0:00:03.130 4M / 412M INFO General (main.cpp : 255) Saving corrected dataset description to /under-test/output/2018_11_08_19_41_18_temp/corrected/corrected.yaml 0:00:03.134 4M / 412M INFO General (main.cpp : 262) All done. Exiting. == Compressing corrected reads (with gzip) == Dataset description file was created: /under-test/output/2018_11_08_19_41_18_temp/corrected/corrected.yaml ===== Read error correction finished. ===== Assembling started. == Running assembler: K21 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K21/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K21/configs/careful_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from N/A, git revision N/A 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 (/under-test/output/2018_11_08_19_41_18_temp/dataset.info) with K=21 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started 0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction 0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0 0:00:00.001 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.207 68M / 132M INFO General (binary_converter.hpp : 117) 1190 reads written 0:00:00.219 4M / 132M INFO General (read_converter.hpp : 87) Converting single reads 0:00:00.511 132M / 260M INFO General (binary_converter.hpp : 117) 2540 reads written 0:00:00.531 4M / 260M INFO General (read_converter.hpp : 95) Converting merged reads 0:00:00.795 132M / 260M INFO General (binary_converter.hpp : 117) 0 reads written 0:00:00.827 4M / 260M INFO General (construction.cpp : 111) Max read length 251 0:00:00.827 4M / 260M INFO General (construction.cpp : 117) Average read length 197.835 0:00:00.827 4M / 260M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.833 4M / 260M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 1 files using 1 threads. This might take a while. 0:00:00.836 4M / 260M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.836 4M / 260M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.836 4M / 260M INFO General (kmer_splitters.hpp : 97) Using cell size of 44564480 0:00:01.006 380M / 756M INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:00:01.009 4M / 756M INFO General (kmer_splitters.hpp : 308) Used 9840 reads 0:00:01.010 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:01.037 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 31759 kmers in total. 0:00:01.037 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:01.046 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:00:01.048 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.048 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:01.050 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:01.050 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:01.050 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 2785280 0:00:01.177 388M / 756M INFO General (kmer_splitters.hpp : 380) Processed 31759 kmers 0:00:01.177 388M / 756M INFO General (kmer_splitters.hpp : 385) Used 31759 kmers. 0:00:01.179 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:01.380 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 31809 kmers in total. 0:00:01.381 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:01.460 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.606 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:01.656 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 23648 bytes occupied (5.9475 bits per kmer). 0:00:01.656 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:00:01.670 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:00:01.674 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping 0:00:01.675 4M / 756M INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K) 0:00:01.675 4M / 756M INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping 0:00:01.710 4M / 756M INFO Early tip clipping (early_simplification.hpp : 184) 3190 22-mers were removed by early tip clipper 0:00:01.711 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:00:01.717 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:00:01.730 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 180 sequences extracted 0:00:01.741 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:00:01.751 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected 0:00:01.754 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:00:01.755 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.755 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.773 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 15264 bytes occupied (3.84496 bits per kmer). 0:00:01.774 4M / 756M INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:00:01.882 4M / 756M INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:00:01.901 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding 0:00:01.901 4M / 756M INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0 0:00:01.901 4M / 756M INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 3 0:00:01.901 4M / 756M INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 4. Coverage mad: 6.63039 0:00:01.901 4M / 756M INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model 0:00:01.914 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 0:00:01.934 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 0:00:01.987 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 0:00:02.086 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 16 0:00:02.366 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 32 0:00:02.701 4M / 756M INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 2.77986. Fitted coverage std. dev: 0.92183 0:00:02.701 4M / 756M INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.0290411 0:00:02.701 4M / 756M INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 1 0:00:02.701 4M / 756M INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 1 0:00:02.701 4M / 756M INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 27341 0:00:02.701 4M / 756M INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 2.77986 0:00:02.701 4M / 756M INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 1 0:00:02.701 4M / 756M INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0 0:00:02.701 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:00:02.704 4M / 756M INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:00:02.705 4M / 756M INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled 0:00:02.705 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:00:02.705 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times 0:00:02.705 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:00:02.705 4M / 756M INFO General (simplification.cpp : 357) Graph simplification started 0:00:02.706 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:02.706 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:00:02.706 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.706 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 3 times 0:00:02.706 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 9 times 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.711 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.711 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.711 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.711 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.712 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.712 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.712 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.712 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.712 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.712 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.712 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.713 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1 times 0:00:02.713 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11 0:00:02.713 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.713 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.713 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.713 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.713 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.714 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.714 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup 0:00:02.714 4M / 756M INFO General (simplification.cpp : 196) PROCEDURE == Post simplification 0:00:02.714 4M / 756M INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled 0:00:02.714 4M / 756M INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled 0:00:02.714 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:02.714 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.714 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.714 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.715 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.715 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.715 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.715 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.716 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.716 4M / 756M INFO General (simplification.cpp : 330) Disrupting self-conjugate edges 0:00:02.716 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges 0:00:02.716 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 32 times 0:00:02.716 4M / 756M INFO General (simplification.cpp : 470) Counting average coverage 0:00:02.716 4M / 756M INFO General (simplification.cpp : 476) Average coverage = 37.0611 0:00:02.716 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.718 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K21/assembly_graph_with_scaffolds.gfa 0:00:02.724 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K21/before_rr.fasta 0:00:02.784 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K21/assembly_graph.fastg 0:00:02.795 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K21/simplified_contigs.fasta 0:00:02.854 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K21/final_contigs.fasta 0:00:02.903 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.904 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K21/assembly_graph_with_scaffolds.gfa 0:00:02.910 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K21/before_rr.fasta 0:00:02.959 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K21/assembly_graph.fastg 0:00:02.970 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K21/simplified_contigs.fasta 0:00:03.023 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K21/final_contigs.fasta 0:00:03.082 4M / 756M INFO General (launch.hpp : 149) SPAdes finished 0:00:03.083 4M / 756M INFO General (main.cpp : 109) Assembling time: 0 hours 0 minutes 3 seconds Max read length detected as 251 Default k-mer sizes were set to [21, 33, 55, 77, 99, 127] because estimated read length (251) is equal to or greater than 250 == Running assembler: K33 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K33/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K33/configs/careful_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from N/A, git revision N/A 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 (/under-test/output/2018_11_08_19_41_18_temp/dataset.info) with K=33 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started 0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction 0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0 0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction 0:00:00.007 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected 0:00:00.014 4M / 4M INFO General (construction.cpp : 111) Max read length 251 0:00:00.014 4M / 4M INFO General (construction.cpp : 117) Average read length 197.835 0:00:00.014 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.016 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 1 files using 1 threads. This might take a while. 0:00:00.017 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.017 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.017 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 22282240 0:00:00.185 380M / 756M INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:00:00.207 4M / 756M INFO General (kmer_splitters.hpp : 308) Used 9840 reads 0:00:00.208 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.240 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 31059 kmers in total. 0:00:00.241 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.255 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:00:00.258 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.258 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:00.260 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.260 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.260 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 1392640 0:00:00.389 388M / 756M INFO General (kmer_splitters.hpp : 380) Processed 31059 kmers 0:00:00.389 388M / 756M INFO General (kmer_splitters.hpp : 385) Used 31059 kmers. 0:00:00.391 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.651 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 31122 kmers in total. 0:00:00.651 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.766 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:00.924 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:00.984 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 23384 bytes occupied (6.01092 bits per kmer). 0:00:00.985 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:00:00.997 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:00:01.002 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping 0:00:01.003 4M / 756M INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K) 0:00:01.003 4M / 756M INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping 0:00:01.053 4M / 756M INFO Early tip clipping (early_simplification.hpp : 184) 3236 34-mers were removed by early tip clipper 0:00:01.053 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:00:01.062 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:00:01.082 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 149 sequences extracted 0:00:01.095 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:00:01.108 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected 0:00:01.112 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:00:01.112 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.112 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.131 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 14944 bytes occupied (3.84919 bits per kmer). 0:00:01.132 4M / 756M INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:00:01.229 4M / 756M INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:00:01.244 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding 0:00:01.244 4M / 756M INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0 0:00:01.244 4M / 756M INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 1 0:00:01.244 4M / 756M WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable 0:00:01.244 4M / 756M INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 1. Coverage mad: 3.31519 0:00:01.244 4M / 756M INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model 0:00:01.247 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 0:00:01.254 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 0:00:01.265 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 0:00:01.297 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 16 0:00:01.337 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 32 0:00:01.366 4M / 756M INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 4.34334. Fitted coverage std. dev: 2.52593 0:00:01.366 4M / 756M INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 2.36071e-08 0:00:01.366 4M / 756M INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 1 0:00:01.366 4M / 756M INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 1 0:00:01.366 4M / 756M INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 24451 0:00:01.366 4M / 756M INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 4.34334 0:00:01.366 4M / 756M INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 1 0:00:01.366 4M / 756M INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0 0:00:01.366 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:00:01.366 4M / 756M INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:00:01.366 4M / 756M INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled 0:00:01.366 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:00:01.366 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times 0:00:01.366 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:00:01.366 4M / 756M INFO General (simplification.cpp : 357) Graph simplification started 0:00:01.366 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:01.366 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:00:01.366 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.366 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2 times 0:00:01.366 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 5 times 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.367 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.367 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.367 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.367 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.368 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.368 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.368 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.368 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.368 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.368 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1 times 0:00:01.368 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.368 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.369 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup 0:00:01.369 4M / 756M INFO General (simplification.cpp : 196) PROCEDURE == Post simplification 0:00:01.369 4M / 756M INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled 0:00:01.369 4M / 756M INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled 0:00:01.369 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.369 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.370 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.370 4M / 756M INFO General (simplification.cpp : 330) Disrupting self-conjugate edges 0:00:01.370 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges 0:00:01.370 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 37 times 0:00:01.370 4M / 756M INFO General (simplification.cpp : 470) Counting average coverage 0:00:01.370 4M / 756M INFO General (simplification.cpp : 476) Average coverage = 36.479 0:00:01.370 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:01.370 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K33/assembly_graph_with_scaffolds.gfa 0:00:01.379 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K33/before_rr.fasta 0:00:01.430 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K33/assembly_graph.fastg 0:00:01.442 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K33/simplified_contigs.fasta 0:00:01.491 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K33/final_contigs.fasta 0:00:01.533 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:01.533 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K33/assembly_graph_with_scaffolds.gfa 0:00:01.539 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K33/before_rr.fasta 0:00:01.580 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K33/assembly_graph.fastg 0:00:01.590 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K33/simplified_contigs.fasta 0:00:01.636 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K33/final_contigs.fasta 0:00:01.675 4M / 756M INFO General (launch.hpp : 149) SPAdes finished 0:00:01.676 4M / 756M INFO General (main.cpp : 109) Assembling time: 0 hours 0 minutes 1 seconds == Running assembler: K55 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K55/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K55/configs/careful_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from N/A, git revision N/A 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 (/under-test/output/2018_11_08_19_41_18_temp/dataset.info) with K=55 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started 0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction 0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0 0:00:00.000 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached 0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction 0:00:00.044 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected 0:00:00.056 4M / 4M INFO General (construction.cpp : 111) Max read length 251 0:00:00.056 4M / 4M INFO General (construction.cpp : 117) Average read length 197.835 0:00:00.056 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.059 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 1 files using 1 threads. This might take a while. 0:00:00.061 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.061 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.061 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 22282240 0:00:00.308 380M / 756M INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:00:00.332 4M / 756M INFO General (kmer_splitters.hpp : 308) Used 9840 reads 0:00:00.332 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.363 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 29437 kmers in total. 0:00:00.363 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.374 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:00:00.376 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.377 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:00.378 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.378 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.378 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 1392640 0:00:00.485 388M / 756M INFO General (kmer_splitters.hpp : 380) Processed 29437 kmers 0:00:00.486 388M / 756M INFO General (kmer_splitters.hpp : 385) Used 29437 kmers. 0:00:00.488 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.735 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 29518 kmers in total. 0:00:00.736 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.857 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.151 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:01.196 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22640 bytes occupied (6.13592 bits per kmer). 0:00:01.196 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:00:01.209 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:00:01.213 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:00:01.217 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:00:01.231 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 356 sequences extracted 0:00:01.245 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:00:01.257 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected 0:00:01.261 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:00:01.261 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.261 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.282 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 14192 bytes occupied (3.85691 bits per kmer). 0:00:01.283 4M / 756M INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:00:01.375 4M / 756M INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:00:01.392 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding 0:00:01.392 4M / 756M INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0 0:00:01.392 4M / 756M INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 1 0:00:01.393 4M / 756M WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable 0:00:01.393 4M / 756M INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 1. Coverage mad: 3.31519 0:00:01.393 4M / 756M INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model 0:00:01.398 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 0:00:01.404 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 0:00:01.417 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 0:00:01.442 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 16 0:00:01.482 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 32 0:00:01.514 4M / 756M INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 3.1363. Fitted coverage std. dev: 1.61399 0:00:01.514 4M / 756M INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1.74504e-08 0:00:01.514 4M / 756M INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 1 0:00:01.514 4M / 756M INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 1 0:00:01.514 4M / 756M INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 23018 0:00:01.514 4M / 756M INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 3.1363 0:00:01.514 4M / 756M INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 1 0:00:01.514 4M / 756M INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0 0:00:01.514 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:00:01.514 4M / 756M INFO General (graph_pack.hpp : 101) Index refill 0:00:01.518 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.518 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:01.520 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:01.520 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:01.520 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 1392640 0:00:01.618 388M / 756M INFO General (edge_index_builders.hpp : 82) Used 712 sequences. 0:00:01.619 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:01.802 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 29437 kmers in total. 0:00:01.802 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:01.882 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:02.040 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:02.085 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22592 bytes occupied (6.13976 bits per kmer). 0:00:02.086 4M / 756M INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:00:02.098 4M / 756M INFO General (edge_index.hpp : 92) Index refilled 0:00:02.102 4M / 756M INFO General (gap_closer.cpp : 159) Preparing shift maps 0:00:02.103 4M / 756M INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:00:02.115 4M / 756M INFO General (gap_closer.cpp : 138) Used 1190 paired reads 0:00:02.116 4M / 756M INFO General (gap_closer.cpp : 140) Merging paired indices 0:00:02.116 4M / 756M INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:00:02.118 4M / 756M INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 46 candidates 0:00:02.118 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:00:02.119 4M / 756M INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:00:02.119 4M / 756M INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled 0:00:02.119 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:00:02.120 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times 0:00:02.120 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:00:02.120 4M / 756M INFO General (simplification.cpp : 357) Graph simplification started 0:00:02.120 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:02.120 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:00:02.120 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.122 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 126 times 0:00:02.123 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 3 times 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.124 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.124 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.124 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.124 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.125 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.125 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.125 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.125 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.125 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.125 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1 times 0:00:02.125 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times 0:00:02.125 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.126 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:02.126 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:02.126 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:00:02.126 4M / 756M INFO General (graph_pack.hpp : 101) Index refill 0:00:02.129 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:02.129 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:02.130 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:02.131 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:02.131 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 1392640 0:00:02.248 388M / 756M INFO General (edge_index_builders.hpp : 82) Used 182 sequences. 0:00:02.248 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:02.431 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 25794 kmers in total. 0:00:02.431 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:02.513 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:02.668 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:02.719 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21008 bytes occupied (6.51562 bits per kmer). 0:00:02.725 4M / 756M INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:00:02.732 4M / 756M INFO General (edge_index.hpp : 92) Index refilled 0:00:02.735 4M / 756M INFO General (gap_closer.cpp : 159) Preparing shift maps 0:00:02.736 4M / 756M INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:00:02.750 4M / 756M INFO General (gap_closer.cpp : 138) Used 1190 paired reads 0:00:02.750 4M / 756M INFO General (gap_closer.cpp : 140) Merging paired indices 0:00:02.751 4M / 756M INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:00:02.751 4M / 756M INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 6 candidates 0:00:02.751 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup 0:00:02.751 4M / 756M INFO General (simplification.cpp : 196) PROCEDURE == Post simplification 0:00:02.751 4M / 756M INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled 0:00:02.751 4M / 756M INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled 0:00:02.751 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:02.751 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.752 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.752 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.752 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.752 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.752 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.752 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.752 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.752 4M / 756M INFO General (simplification.cpp : 330) Disrupting self-conjugate edges 0:00:02.752 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges 0:00:02.764 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 49 times 0:00:02.764 4M / 756M INFO General (simplification.cpp : 470) Counting average coverage 0:00:02.764 4M / 756M INFO General (simplification.cpp : 476) Average coverage = 37.5317 0:00:02.764 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.764 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K55/assembly_graph_with_scaffolds.gfa 0:00:02.769 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K55/before_rr.fasta 0:00:02.787 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K55/assembly_graph.fastg 0:00:02.795 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K55/simplified_contigs.fasta 0:00:02.813 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K55/final_contigs.fasta 0:00:02.831 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.832 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K55/assembly_graph_with_scaffolds.gfa 0:00:02.836 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K55/before_rr.fasta 0:00:02.854 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K55/assembly_graph.fastg 0:00:02.862 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K55/simplified_contigs.fasta 0:00:02.882 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K55/final_contigs.fasta 0:00:02.905 4M / 756M INFO General (launch.hpp : 149) SPAdes finished 0:00:02.910 4M / 756M INFO General (main.cpp : 109) Assembling time: 0 hours 0 minutes 2 seconds == Running assembler: K77 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K77/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K77/configs/careful_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from N/A, git revision N/A 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 (/under-test/output/2018_11_08_19_41_18_temp/dataset.info) with K=77 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started 0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction 0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0 0:00:00.000 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached 0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction 0:00:00.008 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected 0:00:00.012 4M / 4M INFO General (construction.cpp : 111) Max read length 251 0:00:00.012 4M / 4M INFO General (construction.cpp : 117) Average read length 197.835 0:00:00.012 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.014 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 1 files using 1 threads. This might take a while. 0:00:00.015 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.015 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.015 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 14854826 0:00:00.147 380M / 756M INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:00:00.167 4M / 756M INFO General (kmer_splitters.hpp : 308) Used 9840 reads 0:00:00.167 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.195 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 27575 kmers in total. 0:00:00.195 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.205 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:00:00.207 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.207 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:00.208 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.208 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.209 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 928426 0:00:00.311 388M / 756M INFO General (kmer_splitters.hpp : 380) Processed 27575 kmers 0:00:00.311 388M / 756M INFO General (kmer_splitters.hpp : 385) Used 27575 kmers. 0:00:00.313 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.505 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 27663 kmers in total. 0:00:00.505 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.606 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:00.771 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:00.833 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21840 bytes occupied (6.31602 bits per kmer). 0:00:00.833 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:00:00.854 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:00:00.859 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:00:00.863 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:00:00.879 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 343 sequences extracted 0:00:00.891 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:00:00.902 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected 0:00:00.906 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:00:00.906 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.906 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:00.926 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 13328 bytes occupied (3.86669 bits per kmer). 0:00:00.927 4M / 756M INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:00:01.019 4M / 756M INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:00:01.036 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding 0:00:01.036 4M / 756M INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0 0:00:01.036 4M / 756M INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 1 0:00:01.036 4M / 756M WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable 0:00:01.036 4M / 756M INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 1. Coverage mad: 3.31519 0:00:01.036 4M / 756M INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model 0:00:01.041 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 0:00:01.048 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 0:00:01.061 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 0:00:01.084 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 16 0:00:01.127 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 32 0:00:01.164 4M / 756M INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 2.88339. Fitted coverage std. dev: 1.42292 0:00:01.164 4M / 756M INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1.6741e-08 0:00:01.164 4M / 756M INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 1 0:00:01.164 4M / 756M INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 1 0:00:01.164 4M / 756M INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 21362 0:00:01.164 4M / 756M INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 2.88339 0:00:01.164 4M / 756M INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 1 0:00:01.164 4M / 756M INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0 0:00:01.164 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:00:01.164 4M / 756M INFO General (graph_pack.hpp : 101) Index refill 0:00:01.170 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.171 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:01.172 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:01.172 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:01.172 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 928426 0:00:01.294 388M / 756M INFO General (edge_index_builders.hpp : 82) Used 686 sequences. 0:00:01.295 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:01.524 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 27575 kmers in total. 0:00:01.524 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:01.611 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.793 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:01.847 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21760 bytes occupied (6.31296 bits per kmer). 0:00:01.848 4M / 756M INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:00:01.855 4M / 756M INFO General (edge_index.hpp : 92) Index refilled 0:00:01.858 4M / 756M INFO General (gap_closer.cpp : 159) Preparing shift maps 0:00:01.859 4M / 756M INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:00:01.871 4M / 756M INFO General (gap_closer.cpp : 138) Used 1190 paired reads 0:00:01.871 4M / 756M INFO General (gap_closer.cpp : 140) Merging paired indices 0:00:01.871 4M / 756M INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:00:01.874 4M / 756M INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 44 candidates 0:00:01.874 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:00:01.875 4M / 756M INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:00:01.875 4M / 756M INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled 0:00:01.875 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:00:01.875 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times 0:00:01.875 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:00:01.875 4M / 756M INFO General (simplification.cpp : 357) Graph simplification started 0:00:01.875 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:01.875 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:00:01.875 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.877 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 126 times 0:00:01.877 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.877 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1 times 0:00:01.877 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.878 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10 0:00:01.878 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.879 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.879 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.879 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:00:01.879 4M / 756M INFO General (graph_pack.hpp : 101) Index refill 0:00:01.883 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.883 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:01.884 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:01.884 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:01.884 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 928426 0:00:02.003 388M / 756M INFO General (edge_index_builders.hpp : 82) Used 178 sequences. 0:00:02.004 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:02.211 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 24274 kmers in total. 0:00:02.212 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:02.298 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:02.452 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:02.502 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 20368 bytes occupied (6.7127 bits per kmer). 0:00:02.508 4M / 756M INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:00:02.514 4M / 756M INFO General (edge_index.hpp : 92) Index refilled 0:00:02.517 4M / 756M INFO General (gap_closer.cpp : 159) Preparing shift maps 0:00:02.518 4M / 756M INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:00:02.531 4M / 756M INFO General (gap_closer.cpp : 138) Used 1190 paired reads 0:00:02.531 4M / 756M INFO General (gap_closer.cpp : 140) Merging paired indices 0:00:02.532 4M / 756M INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:00:02.532 4M / 756M INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 1 candidates 0:00:02.533 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup 0:00:02.533 4M / 756M INFO General (simplification.cpp : 196) PROCEDURE == Post simplification 0:00:02.533 4M / 756M INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled 0:00:02.533 4M / 756M INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled 0:00:02.533 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:02.533 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.533 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.533 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.533 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.533 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.533 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.534 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.534 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.534 4M / 756M INFO General (simplification.cpp : 330) Disrupting self-conjugate edges 0:00:02.534 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges 0:00:02.550 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 63 times 0:00:02.550 4M / 756M INFO General (simplification.cpp : 470) Counting average coverage 0:00:02.551 4M / 756M INFO General (simplification.cpp : 476) Average coverage = 39.0497 0:00:02.551 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.551 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K77/assembly_graph_with_scaffolds.gfa 0:00:02.556 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K77/before_rr.fasta 0:00:02.567 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K77/assembly_graph.fastg 0:00:02.573 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K77/simplified_contigs.fasta 0:00:02.584 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K77/final_contigs.fasta 0:00:02.597 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.598 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K77/assembly_graph_with_scaffolds.gfa 0:00:02.603 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K77/before_rr.fasta 0:00:02.617 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K77/assembly_graph.fastg 0:00:02.623 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K77/simplified_contigs.fasta 0:00:02.634 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K77/final_contigs.fasta 0:00:02.649 4M / 756M INFO General (launch.hpp : 149) SPAdes finished 0:00:02.654 4M / 756M INFO General (main.cpp : 109) Assembling time: 0 hours 0 minutes 2 seconds == Running assembler: K99 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K99/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K99/configs/careful_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from N/A, git revision N/A 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 (/under-test/output/2018_11_08_19_41_18_temp/dataset.info) with K=99 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started 0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction 0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0 0:00:00.000 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached 0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction 0:00:00.010 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected 0:00:00.015 4M / 4M INFO General (construction.cpp : 111) Max read length 251 0:00:00.015 4M / 4M INFO General (construction.cpp : 117) Average read length 197.835 0:00:00.015 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.018 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 1 files using 1 threads. This might take a while. 0:00:00.019 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.019 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.019 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 11141120 0:00:00.157 380M / 756M INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:00:00.183 4M / 756M INFO General (kmer_splitters.hpp : 308) Used 9840 reads 0:00:00.183 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.216 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 25545 kmers in total. 0:00:00.217 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.234 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:00:00.237 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.237 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:00.238 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.238 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.238 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 696320 0:00:00.368 388M / 756M INFO General (kmer_splitters.hpp : 380) Processed 25545 kmers 0:00:00.368 388M / 756M INFO General (kmer_splitters.hpp : 385) Used 25545 kmers. 0:00:00.370 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.586 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 25636 kmers in total. 0:00:00.586 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.682 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:00.877 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:00.928 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 20944 bytes occupied (6.53581 bits per kmer). 0:00:00.928 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:00:00.945 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:00:00.950 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:00:00.955 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:00:00.971 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 333 sequences extracted 0:00:00.983 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:00:00.998 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected 0:00:01.002 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:00:01.002 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.002 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.034 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 12392 bytes occupied (3.88084 bits per kmer). 0:00:01.035 4M / 756M INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:00:01.112 4M / 756M INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:00:01.129 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding 0:00:01.130 4M / 756M INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0 0:00:01.130 4M / 756M INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 1 0:00:01.130 4M / 756M WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable 0:00:01.130 4M / 756M INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 1. Coverage mad: 3.31519 0:00:01.130 4M / 756M INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model 0:00:01.135 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 0:00:01.141 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 0:00:01.156 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 0:00:01.178 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 16 0:00:01.218 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 32 0:00:01.296 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 64 0:00:01.320 4M / 756M INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 2.8778. Fitted coverage std. dev: 1.3229 0:00:01.320 4M / 756M INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1.02128e-07 0:00:01.320 4M / 756M INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 1 0:00:01.320 4M / 756M INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 1 0:00:01.320 4M / 756M INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 19656 0:00:01.320 4M / 756M INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 2.8778 0:00:01.320 4M / 756M INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 1 0:00:01.320 4M / 756M INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0 0:00:01.320 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:00:01.320 4M / 756M INFO General (graph_pack.hpp : 101) Index refill 0:00:01.324 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.324 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:01.326 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:01.326 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:01.326 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 696320 0:00:01.412 388M / 756M INFO General (edge_index_builders.hpp : 82) Used 666 sequences. 0:00:01.413 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:01.571 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 25545 kmers in total. 0:00:01.571 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:01.645 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.770 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:01.821 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 20888 bytes occupied (6.54155 bits per kmer). 0:00:01.822 4M / 756M INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:00:01.830 4M / 756M INFO General (edge_index.hpp : 92) Index refilled 0:00:01.834 4M / 756M INFO General (gap_closer.cpp : 159) Preparing shift maps 0:00:01.835 4M / 756M INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:00:01.847 4M / 756M INFO General (gap_closer.cpp : 138) Used 1190 paired reads 0:00:01.847 4M / 756M INFO General (gap_closer.cpp : 140) Merging paired indices 0:00:01.847 4M / 756M INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:00:01.850 4M / 756M INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 40 candidates 0:00:01.850 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:00:01.851 4M / 756M INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:00:01.851 4M / 756M INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled 0:00:01.851 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:00:01.851 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times 0:00:01.851 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:00:01.851 4M / 756M INFO General (simplification.cpp : 357) Graph simplification started 0:00:01.851 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:01.851 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:00:01.851 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.853 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 119 times 0:00:01.853 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1 times 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.854 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.854 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.854 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.854 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.855 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.855 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.855 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.855 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.855 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.855 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.855 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.855 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.855 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:00:01.855 4M / 756M INFO General (graph_pack.hpp : 101) Index refill 0:00:01.859 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.859 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:01.860 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:01.860 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:01.860 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 696320 0:00:01.979 388M / 756M INFO General (edge_index_builders.hpp : 82) Used 184 sequences. 0:00:01.980 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:02.167 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 22840 kmers in total. 0:00:02.167 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:02.241 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:02.372 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:02.416 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 19520 bytes occupied (6.83713 bits per kmer). 0:00:02.421 4M / 756M INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:00:02.427 4M / 756M INFO General (edge_index.hpp : 92) Index refilled 0:00:02.430 4M / 756M INFO General (gap_closer.cpp : 159) Preparing shift maps 0:00:02.430 4M / 756M INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:00:02.442 4M / 756M INFO General (gap_closer.cpp : 138) Used 1190 paired reads 0:00:02.443 4M / 756M INFO General (gap_closer.cpp : 140) Merging paired indices 0:00:02.443 4M / 756M INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:00:02.443 4M / 756M INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 1 candidates 0:00:02.444 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup 0:00:02.444 4M / 756M INFO General (simplification.cpp : 196) PROCEDURE == Post simplification 0:00:02.444 4M / 756M INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled 0:00:02.444 4M / 756M INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled 0:00:02.444 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.444 4M / 756M INFO General (simplification.cpp : 330) Disrupting self-conjugate edges 0:00:02.444 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges 0:00:02.457 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 71 times 0:00:02.457 4M / 756M INFO General (simplification.cpp : 470) Counting average coverage 0:00:02.457 4M / 756M INFO General (simplification.cpp : 476) Average coverage = 36.786 0:00:02.457 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.458 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K99/assembly_graph_with_scaffolds.gfa 0:00:02.462 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K99/before_rr.fasta 0:00:02.470 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K99/assembly_graph.fastg 0:00:02.473 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K99/simplified_contigs.fasta 0:00:02.481 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K99/final_contigs.fasta 0:00:02.491 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.491 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K99/assembly_graph_with_scaffolds.gfa 0:00:02.494 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K99/before_rr.fasta 0:00:02.503 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K99/assembly_graph.fastg 0:00:02.508 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K99/simplified_contigs.fasta 0:00:02.515 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K99/final_contigs.fasta 0:00:02.526 4M / 756M INFO General (launch.hpp : 149) SPAdes finished 0:00:02.531 4M / 756M INFO General (main.cpp : 109) Assembling time: 0 hours 0 minutes 2 seconds == Running assembler: K127 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K127/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /under-test/output/2018_11_08_19_41_18_temp/K127/configs/careful_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from N/A, git revision N/A 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 (/under-test/output/2018_11_08_19_41_18_temp/dataset.info) with K=127 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.000 4M / 4M INFO General (launch.hpp : 51) SPAdes started 0:00:00.000 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction 0:00:00.000 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0 0:00:00.000 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached 0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction 0:00:00.006 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected 0:00:00.011 4M / 4M INFO General (construction.cpp : 111) Max read length 251 0:00:00.011 4M / 4M INFO General (construction.cpp : 117) Average read length 197.835 0:00:00.011 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.013 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 1 files using 1 threads. This might take a while. 0:00:00.013 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.013 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.013 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 11141120 0:00:00.114 380M / 756M INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:00:00.133 4M / 756M INFO General (kmer_splitters.hpp : 308) Used 9840 reads 0:00:00.134 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.160 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 22877 kmers in total. 0:00:00.161 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.171 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:00:00.173 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.173 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:00.174 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.174 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:00.174 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 696320 0:00:00.321 388M / 756M INFO General (kmer_splitters.hpp : 380) Processed 22877 kmers 0:00:00.321 388M / 756M INFO General (kmer_splitters.hpp : 385) Used 22877 kmers. 0:00:00.323 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:00.514 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 22973 kmers in total. 0:00:00.515 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:00.588 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:00.737 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:00.782 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 19656 bytes occupied (6.8449 bits per kmer). 0:00:00.782 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:00:00.794 4M / 756M INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:00:00.797 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:00:00.801 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:00:00.813 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 320 sequences extracted 0:00:00.824 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:00:00.837 4M / 756M INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected 0:00:00.841 4M / 756M INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:00:00.841 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.841 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:00.861 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 11144 bytes occupied (3.89701 bits per kmer). 0:00:00.862 4M / 756M INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:00:00.914 4M / 756M INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:00:00.931 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding 0:00:00.931 4M / 756M INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0 0:00:00.931 4M / 756M INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 1 0:00:00.931 4M / 756M WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable 0:00:00.931 4M / 756M INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 1. Coverage mad: 3.31519 0:00:00.931 4M / 756M INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model 0:00:00.935 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 0:00:00.940 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 0:00:00.953 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 0:00:00.982 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 16 0:00:01.027 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 32 0:00:01.112 4M / 756M INFO General (kmer_coverage_model.cpp : 295) ... iteration 64 0:00:01.174 4M / 756M INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 2.61106. Fitted coverage std. dev: 1.05898 0:00:01.175 4M / 756M INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1.45675e-07 0:00:01.175 4M / 756M INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 1 0:00:01.175 4M / 756M INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 1 0:00:01.175 4M / 756M INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 17499 0:00:01.175 4M / 756M INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 2.61106 0:00:01.175 4M / 756M INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 1 0:00:01.175 4M / 756M INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0 0:00:01.175 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:00:01.175 4M / 756M INFO General (graph_pack.hpp : 101) Index refill 0:00:01.181 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.182 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:01.183 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:01.183 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:01.183 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 696320 0:00:01.303 388M / 756M INFO General (edge_index_builders.hpp : 82) Used 640 sequences. 0:00:01.304 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:01.512 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 22877 kmers in total. 0:00:01.512 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:01.606 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:01.755 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:01.810 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 19592 bytes occupied (6.85125 bits per kmer). 0:00:01.811 4M / 756M INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:00:01.816 4M / 756M INFO General (edge_index.hpp : 92) Index refilled 0:00:01.818 4M / 756M INFO General (gap_closer.cpp : 159) Preparing shift maps 0:00:01.819 4M / 756M INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:00:01.835 4M / 756M INFO General (gap_closer.cpp : 138) Used 1190 paired reads 0:00:01.835 4M / 756M INFO General (gap_closer.cpp : 140) Merging paired indices 0:00:01.836 4M / 756M INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:00:01.839 4M / 756M INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 40 candidates 0:00:01.839 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:00:01.840 4M / 756M INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:00:01.840 4M / 756M INFO General (simplification.cpp : 62) Most init cleaning disabled on main iteration 0:00:01.840 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:00:01.840 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times 0:00:01.840 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:00:01.840 4M / 756M INFO General (simplification.cpp : 357) Graph simplification started 0:00:01.840 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:01.840 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:00:01.840 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 112 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.843 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.843 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.843 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.843 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.843 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.844 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.844 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.844 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.844 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.844 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.844 4M / 756M INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:00:01.844 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:00:01.844 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:00:01.845 4M / 756M INFO General (graph_pack.hpp : 101) Index refill 0:00:01.851 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:01.851 4M / 756M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 16 files using 1 threads. This might take a while. 0:00:01.852 4M / 756M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:01.852 4M / 756M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.332031 Gb 0:00:01.852 4M / 756M INFO General (kmer_splitters.hpp : 97) Using cell size of 696320 0:00:01.963 388M / 756M INFO General (edge_index_builders.hpp : 82) Used 192 sequences. 0:00:01.963 4M / 756M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:00:02.153 4M / 756M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 20649 kmers in total. 0:00:02.154 4M / 756M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:00:02.237 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:00:02.381 4M / 756M INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:00:02.429 4M / 756M INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 18600 bytes occupied (7.20616 bits per kmer). 0:00:02.434 4M / 756M INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:00:02.439 4M / 756M INFO General (edge_index.hpp : 92) Index refilled 0:00:02.443 4M / 756M INFO General (gap_closer.cpp : 159) Preparing shift maps 0:00:02.443 4M / 756M INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:00:02.454 4M / 756M INFO General (gap_closer.cpp : 138) Used 1190 paired reads 0:00:02.454 4M / 756M INFO General (gap_closer.cpp : 140) Merging paired indices 0:00:02.454 4M / 756M INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:00:02.454 4M / 756M INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 0 candidates 0:00:02.455 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup 0:00:02.455 4M / 756M INFO General (simplification.cpp : 196) PROCEDURE == Post simplification 0:00:02.455 4M / 756M INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled 0:00:02.455 4M / 756M INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled 0:00:02.455 4M / 756M INFO General (graph_simplification.hpp : 634) Creating parallel br instance 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:00:02.455 4M / 756M INFO General (simplification.cpp : 330) Disrupting self-conjugate edges 0:00:02.455 4M / 756M INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges 0:00:02.470 4M / 756M INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 80 times 0:00:02.471 4M / 756M INFO General (simplification.cpp : 470) Counting average coverage 0:00:02.471 4M / 756M INFO General (simplification.cpp : 476) Average coverage = 33.3357 0:00:02.471 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Mismatch Correction 0:00:02.471 4M / 756M INFO General (graph_pack.hpp : 109) Normalizing k-mer map. Total 0 kmers to process 0:00:02.471 4M / 756M INFO General (graph_pack.hpp : 111) Normalizing done 0:00:02.538 4M / 756M INFO General (mismatch_shall_not_pass.hp: 189) Finished collecting potential mismatches positions 0:00:02.538 4M / 756M INFO General (mismatch_shall_not_pass.hp: 290) All edges processed 0:00:02.538 4M / 756M INFO General (mismatch_correction.cpp : 27) Corrected 0 nucleotides 0:00:02.540 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:02.540 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K127/assembly_graph_with_scaffolds.gfa 0:00:02.544 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K127/before_rr.fasta 0:00:02.551 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K127/assembly_graph.fastg 0:00:02.556 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K127/simplified_contigs.fasta 0:00:02.563 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K127/intermediate_contigs.fasta 0:00:02.573 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Paired Information Counting 0:00:02.573 4M / 756M INFO General (graph_pack.hpp : 109) Normalizing k-mer map. Total 0 kmers to process 0:00:02.573 4M / 756M INFO General (graph_pack.hpp : 111) Normalizing done 0:00:02.573 4M / 756M INFO General (pair_info_count.cpp : 320) Min edge length for estimation: 1482 0:00:02.573 4M / 756M INFO General (pair_info_count.cpp : 331) Estimating insert size for library #0 0:00:02.573 4M / 756M INFO General (pair_info_count.cpp : 190) Estimating insert size (takes a while) 0:00:02.595 36M / 756M INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:00:02.636 36M / 756M INFO General (sequence_mapper_notifier.h: 98) Total 1190 reads processed 0:00:03.960 36M / 756M INFO General (pair_info_count.cpp : 209) Edge pairs: 67108864 (rough upper limit) 0:00:03.961 36M / 756M INFO General (pair_info_count.cpp : 213) 742 paired reads (62.3529% of all) aligned to long edges 0:00:03.969 4M / 756M INFO General (pair_info_count.cpp : 354) Insert size = 301.964, deviation = 137.038, left quantile = 157, right quantile = 496, read length = 251 0:00:04.059 196M / 756M INFO General (pair_info_count.cpp : 371) Filtering data for library #0 0:00:04.065 196M / 756M INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:00:04.079 196M / 756M INFO General (sequence_mapper_notifier.h: 98) Total 1190 reads processed 0:00:04.080 196M / 756M INFO General (pair_info_count.cpp : 383) Mapping library #0 0:00:04.080 196M / 756M INFO General (pair_info_count.cpp : 385) Mapping paired reads (takes a while) 0:00:04.080 196M / 756M INFO General (pair_info_count.cpp : 289) Left insert size quantile 157, right insert size quantile 496, filtering threshold 2, rounding threshold 0 0:00:04.094 208M / 756M INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:00:04.111 208M / 756M INFO General (sequence_mapper_notifier.h: 98) Total 1190 reads processed 0:00:04.161 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Distance Estimation 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 173) Processing library #0 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 149) Weight Filter Done 0:00:04.161 4M / 756M INFO DistanceEstimator (distance_estimation.hpp : 116) Using SIMPLE distance estimator 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 34) Filtering info 0:00:04.161 4M / 756M INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 32 0:00:04.161 4M / 756M INFO General (pair_info_filters.hpp : 263) Done filtering 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 156) Refining clustered pair information 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 158) The refining of clustered pair information has been finished 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 160) Improving paired information 0:00:04.161 4M / 756M INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 0; contradictional = 0 0:00:04.161 4M / 756M INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 0; contradictional = 0 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 103) Filling scaffolding index 0:00:04.161 4M / 756M INFO DistanceEstimator (distance_estimation.hpp : 116) Using SMOOTHING distance estimator 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 34) Filtering info 0:00:04.161 4M / 756M INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 32 0:00:04.161 4M / 756M INFO General (pair_info_filters.hpp : 263) Done filtering 0:00:04.161 4M / 756M INFO General (distance_estimation.cpp : 182) Clearing raw paired index 0:00:04.161 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Repeat Resolving 0:00:04.161 4M / 756M INFO General (repeat_resolving.cpp : 69) Using Path-Extend repeat resolving 0:00:04.161 4M / 756M INFO General (launcher.cpp : 477) ExSPAnder repeat resolving tool started 0:00:04.164 4M / 756M INFO General (launcher.cpp : 392) Creating main extenders, unique edge length = 2000 0:00:04.165 4M / 756M INFO General (extenders_logic.cpp : 275) Estimated coverage of library #0 is 33.3357 0:00:04.165 4M / 756M INFO General (extenders_logic.cpp : 275) Estimated coverage of library #0 is 33.3357 0:00:04.167 4M / 756M INFO General (extenders_logic.cpp : 472) Using 1 paired-end library 0:00:04.167 4M / 756M INFO General (extenders_logic.cpp : 473) Using 1 paired-end scaffolding library 0:00:04.167 4M / 756M INFO General (extenders_logic.cpp : 474) Using 0 single read libraries 0:00:04.167 4M / 756M INFO General (launcher.cpp : 420) Total number of extenders is 3 0:00:04.167 4M / 756M INFO General (path_extender.hpp : 885) Processed 0 paths from 16 (0%) 0:00:04.167 4M / 756M INFO General (path_extender.hpp : 885) Processed 2 paths from 16 (12%) 0:00:04.167 4M / 756M INFO General (path_extender.hpp : 885) Processed 4 paths from 16 (25%) 0:00:04.168 4M / 756M INFO General (path_extender.hpp : 885) Processed 6 paths from 16 (37%) 0:00:04.168 4M / 756M INFO General (path_extender.hpp : 885) Processed 8 paths from 16 (50%) 0:00:04.168 4M / 756M INFO General (path_extender.hpp : 885) Processed 10 paths from 16 (62%) 0:00:04.168 4M / 756M INFO General (path_extender.hpp : 885) Processed 12 paths from 16 (75%) 0:00:04.168 4M / 756M INFO General (path_extender.hpp : 885) Processed 14 paths from 16 (87%) 0:00:04.169 4M / 756M INFO General (launcher.cpp : 234) Finalizing paths 0:00:04.169 4M / 756M INFO General (launcher.cpp : 236) Deduplicating paths 0:00:04.169 4M / 756M INFO General (launcher.cpp : 240) Paths deduplicated 0:00:04.169 4M / 756M INFO PEResolver (pe_resolver.hpp : 295) Removing overlaps 0:00:04.169 4M / 756M INFO PEResolver (pe_resolver.hpp : 298) Sorting paths 0:00:04.169 4M / 756M INFO PEResolver (pe_resolver.hpp : 305) Marking overlaps 0:00:04.169 4M / 756M INFO OverlapRemover (pe_resolver.hpp : 130) Marking start/end overlaps 0:00:04.169 4M / 756M INFO OverlapRemover (pe_resolver.hpp : 133) Marking remaining overlaps 0:00:04.169 4M / 756M INFO PEResolver (pe_resolver.hpp : 308) Splitting paths 0:00:04.169 4M / 756M INFO PEResolver (pe_resolver.hpp : 313) Deduplicating paths 0:00:04.169 4M / 756M INFO PEResolver (pe_resolver.hpp : 315) Overlaps removed 0:00:04.169 4M / 756M INFO General (launcher.cpp : 257) Paths finalized 0:00:04.169 4M / 756M INFO General (launcher.cpp : 427) Closing gaps in paths 0:00:04.169 4M / 756M INFO General (launcher.cpp : 455) Gap closing completed 0:00:04.169 4M / 756M INFO General (launcher.cpp : 286) Traversing tandem repeats 0:00:04.170 4M / 756M INFO General (launcher.cpp : 296) Traversed 0 loops 0:00:04.170 4M / 756M INFO General (launcher.cpp : 234) Finalizing paths 0:00:04.170 4M / 756M INFO General (launcher.cpp : 236) Deduplicating paths 0:00:04.170 4M / 756M INFO General (launcher.cpp : 240) Paths deduplicated 0:00:04.170 4M / 756M INFO PEResolver (pe_resolver.hpp : 295) Removing overlaps 0:00:04.170 4M / 756M INFO PEResolver (pe_resolver.hpp : 298) Sorting paths 0:00:04.170 4M / 756M INFO PEResolver (pe_resolver.hpp : 305) Marking overlaps 0:00:04.170 4M / 756M INFO OverlapRemover (pe_resolver.hpp : 130) Marking start/end overlaps 0:00:04.170 4M / 756M INFO OverlapRemover (pe_resolver.hpp : 133) Marking remaining overlaps 0:00:04.170 4M / 756M INFO PEResolver (pe_resolver.hpp : 308) Splitting paths 0:00:04.170 4M / 756M INFO PEResolver (pe_resolver.hpp : 313) Deduplicating paths 0:00:04.170 4M / 756M INFO PEResolver (pe_resolver.hpp : 315) Overlaps removed 0:00:04.171 4M / 756M INFO General (launcher.cpp : 257) Paths finalized 0:00:04.171 4M / 756M INFO General (launcher.cpp : 529) ExSPAnder repeat resolving tool finished 0:00:04.171 4M / 756M INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:00:04.171 4M / 756M INFO General (contig_output_stage.cpp : 40) Writing GFA to /under-test/output/2018_11_08_19_41_18_temp//K127/assembly_graph_with_scaffolds.gfa 0:00:04.174 4M / 756M INFO General (contig_output.hpp : 22) Outputting contigs to /under-test/output/2018_11_08_19_41_18_temp//K127/before_rr.fasta 0:00:04.185 4M / 756M INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /under-test/output/2018_11_08_19_41_18_temp//K127/assembly_graph.fastg 0:00:04.192 4M / 756M INFO General (contig_output_stage.cpp : 20) Outputting FastG paths to /under-test/output/2018_11_08_19_41_18_temp//K127/final_contigs.paths 0:00:04.198 4M / 756M INFO General (contig_output_stage.cpp : 20) Outputting FastG paths to /under-test/output/2018_11_08_19_41_18_temp//K127/scaffolds.paths 0:00:04.208 4M / 756M INFO General (launch.hpp : 149) SPAdes finished 0:00:04.215 4M / 756M INFO General (main.cpp : 109) Assembling time: 0 hours 0 minutes 4 seconds ===== Assembling finished. Used k-mer sizes: 21, 33, 55, 77, 99, 127 ===== Mismatch correction started. == Processing of contigs == Running contig polishing tool: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-corrector-core /under-test/output/2018_11_08_19_41_18_temp/mismatch_corrector/contigs/configs/corrector.info /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta == Dataset description file was created: /under-test/output/2018_11_08_19_41_18_temp/mismatch_corrector/contigs/configs/corrector.info /under-test/output/2018_11_08_19_41_18_temp/mismatch_corrector/contigs/configs/log.properties 0:00:00.001 4M / 4M INFO General (main.cpp : 58) Starting MismatchCorrector, built from N/A, git revision N/A 0:00:00.002 4M / 4M INFO General (main.cpp : 59) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.002 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 195) Splitting assembly... 0:00:00.002 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 196) Assembly file: /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta 0:00:00.039 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 203) Processing paired sublib of number 0 0:00:00.040 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 206) /under-test/output/forward.fastq.gz_mapped.fq /under-test/output/reverse.fastq.gz_mapped.fq 0:00:00.041 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 140) Running bwa index ...: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa index -a is /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta [bwa_index] Pack FASTA... 0.00 sec [bwa_index] Construct BWT for the packed sequence... [bwa_index] 0.00 seconds elapse. [bwa_index] Update BWT... 0.00 sec [bwa_index] Pack forward-only FASTA... 0.00 sec [bwa_index] Construct SA from BWT and Occ... 0.01 sec [main] Version: 0.7.12-r1039 [main] CMD: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa index -a is /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta [main] Real time: 0.047 sec; CPU: 0.010 sec 0:00:00.112 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 149) Running bwa mem ...:/root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa mem -v 1 -t 1 /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta /under-test/output/forward.fastq.gz_mapped.fq /under-test/output/reverse.fastq.gz_mapped.fq > /under-test/output/2018_11_08_19_41_18_temp/tmp/corrector_9_hCzp/lib0_t4Rk17/tmp.sam [main] Version: 0.7.12-r1039 [main] CMD: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa mem -v 1 -t 1 /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta /under-test/output/forward.fastq.gz_mapped.fq /under-test/output/reverse.fastq.gz_mapped.fq [main] Real time: 0.169 sec; CPU: 0.130 sec 0:00:00.289 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 209) Adding samfile /under-test/output/2018_11_08_19_41_18_temp/tmp/corrector_9_hCzp/lib0_t4Rk17/tmp.sam 0:00:00.446 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 219) Processing single sublib of number 1 0:00:00.447 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 221) /under-test/output/forward.fastq.gz_combined.fq 0:00:00.448 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 165) Running bwa index ...: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa index -a is /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta [bwa_index] Pack FASTA... 0.00 sec [bwa_index] Construct BWT for the packed sequence... [bwa_index] 0.00 seconds elapse. [bwa_index] Update BWT... 0.00 sec [bwa_index] Pack forward-only FASTA... 0.00 sec [bwa_index] Construct SA from BWT and Occ... 0.00 sec [main] Version: 0.7.12-r1039 [main] CMD: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa index -a is /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta [main] Real time: 0.045 sec; CPU: 0.000 sec 0:00:00.497 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 173) Running bwa mem ...:/root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa mem -v 1 -t 1 /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta /under-test/output/forward.fastq.gz_combined.fq > /under-test/output/2018_11_08_19_41_18_temp/tmp/corrector_9_hCzp/lib1_54xpi4/tmp.sam [main] Version: 0.7.12-r1039 [main] CMD: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa mem -v 1 -t 1 /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_contigs.fasta /under-test/output/forward.fastq.gz_combined.fq [main] Real time: 0.190 sec; CPU: 0.160 sec 0:00:00.698 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 224) Adding samfile /under-test/output/2018_11_08_19_41_18_temp/tmp/corrector_9_hCzp/lib1_54xpi4/tmp.sam 0:00:00.845 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 235) Processing contigs 0:00:01.347 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 255) Gluing processed contigs 0:00:01.377 4M / 4M INFO General (main.cpp : 72) Correcting time: 0 hours 0 minutes 1 seconds == Processing of scaffolds == Running contig polishing tool: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-corrector-core /under-test/output/2018_11_08_19_41_18_temp/mismatch_corrector/scaffolds/configs/corrector.info /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta == Dataset description file was created: /under-test/output/2018_11_08_19_41_18_temp/mismatch_corrector/scaffolds/configs/corrector.info /under-test/output/2018_11_08_19_41_18_temp/mismatch_corrector/scaffolds/configs/log.properties 0:00:00.001 4M / 4M INFO General (main.cpp : 58) Starting MismatchCorrector, built from N/A, git revision N/A 0:00:00.002 4M / 4M INFO General (main.cpp : 59) Maximum # of threads to use (adjusted due to OMP capabilities): 1 0:00:00.002 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 195) Splitting assembly... 0:00:00.002 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 196) Assembly file: /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta 0:00:00.059 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 203) Processing paired sublib of number 0 0:00:00.059 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 206) /under-test/output/forward.fastq.gz_mapped.fq /under-test/output/reverse.fastq.gz_mapped.fq 0:00:00.060 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 140) Running bwa index ...: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa index -a is /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta [bwa_index] Pack FASTA... 0.00 sec [bwa_index] Construct BWT for the packed sequence... [bwa_index] 0.00 seconds elapse. [bwa_index] Update BWT... 0.00 sec [bwa_index] Pack forward-only FASTA... 0.00 sec [bwa_index] Construct SA from BWT and Occ... 0.01 sec [main] Version: 0.7.12-r1039 [main] CMD: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa index -a is /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta [main] Real time: 0.047 sec; CPU: 0.010 sec 0:00:00.113 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 149) Running bwa mem ...:/root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa mem -v 1 -t 1 /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta /under-test/output/forward.fastq.gz_mapped.fq /under-test/output/reverse.fastq.gz_mapped.fq > /under-test/output/2018_11_08_19_41_18_temp/tmp/corrector_XpAWA0/lib0_u1dRiR/tmp.sam [main] Version: 0.7.12-r1039 [main] CMD: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa mem -v 1 -t 1 /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta /under-test/output/forward.fastq.gz_mapped.fq /under-test/output/reverse.fastq.gz_mapped.fq [main] Real time: 0.178 sec; CPU: 0.150 sec 0:00:00.300 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 209) Adding samfile /under-test/output/2018_11_08_19_41_18_temp/tmp/corrector_XpAWA0/lib0_u1dRiR/tmp.sam 0:00:00.434 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 219) Processing single sublib of number 1 0:00:00.434 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 221) /under-test/output/forward.fastq.gz_combined.fq 0:00:00.436 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 165) Running bwa index ...: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa index -a is /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta [bwa_index] Pack FASTA... 0.00 sec [bwa_index] Construct BWT for the packed sequence... [bwa_index] 0.00 seconds elapse. [bwa_index] Update BWT... 0.00 sec [bwa_index] Pack forward-only FASTA... 0.00 sec [bwa_index] Construct SA from BWT and Occ... 0.00 sec [main] Version: 0.7.12-r1039 [main] CMD: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa index -a is /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta [main] Real time: 0.041 sec; CPU: 0.000 sec 0:00:00.482 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 173) Running bwa mem ...:/root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa mem -v 1 -t 1 /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta /under-test/output/forward.fastq.gz_combined.fq > /under-test/output/2018_11_08_19_41_18_temp/tmp/corrector_XpAWA0/lib1_w0t6nR/tmp.sam [main] Version: 0.7.12-r1039 [main] CMD: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-bwa mem -v 1 -t 1 /under-test/output/2018_11_08_19_41_18_temp/misc/assembled_scaffolds.fasta /under-test/output/forward.fastq.gz_combined.fq [main] Real time: 0.206 sec; CPU: 0.180 sec 0:00:00.696 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 224) Adding samfile /under-test/output/2018_11_08_19_41_18_temp/tmp/corrector_XpAWA0/lib1_w0t6nR/tmp.sam 0:00:00.853 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 235) Processing contigs 0:00:01.464 4M / 4M INFO DatasetProcessor (dataset_processor.cpp : 255) Gluing processed contigs 0:00:01.531 4M / 4M INFO General (main.cpp : 72) Correcting time: 0 hours 0 minutes 1 seconds ===== Mismatch correction finished. * Corrected reads are in /under-test/output/2018_11_08_19_41_18_temp/corrected/ * Assembled contigs are in /under-test/output/2018_11_08_19_41_18_temp/contigs.fasta * Assembled scaffolds are in /under-test/output/2018_11_08_19_41_18_temp/scaffolds.fasta * Assembly graph is in /under-test/output/2018_11_08_19_41_18_temp/assembly_graph.fastg * Assembly graph in GFA format is in /under-test/output/2018_11_08_19_41_18_temp/assembly_graph_with_scaffolds.gfa * Paths in the assembly graph corresponding to the contigs are in /under-test/output/2018_11_08_19_41_18_temp/contigs.paths * Paths in the assembly graph corresponding to the scaffolds are in /under-test/output/2018_11_08_19_41_18_temp/scaffolds.paths ======= SPAdes pipeline finished WITH WARNINGS! === Error correction and assembling warnings: * 0:00:01.244 4M / 756M WARN General (kmer_coverage_model.cpp : 218) Too many erroneous kmers, the estimates might be unreliable ======= Warnings saved to /under-test/output/2018_11_08_19_41_18_temp/warnings.log SPAdes log can be found here: /under-test/output/2018_11_08_19_41_18_temp/spades.log Thank you for using SPAdes! Building a new DB, current time: 11/08/2018 19:51:37 New DB name: /under-test/output/forward.fastq.gz_H_and_O_and_specific_genes.fasta_mem.fasta_db New DB title: forward.fastq.gz_H_and_O_and_specific_genes.fasta_mem.fasta Sequence type: Nucleotide Keep MBits: T Maximum file size: 1000000000B Adding sequences from FASTA; added 16 sequences in 0.0294061 seconds. Command line: /root/miniconda3/envs/seqsero/bin/spades.py --careful --pe1-s /under-test/output/forward.fastq.gz_combined.fq --pe1-1 /under-test/output/forward.fastq.gz_mapped.fq --pe1-2 /under-test/output/reverse.fastq.gz_mapped.fq -t 4 -o /under-test/output/2018_11_08_20_00_08_temp System information: SPAdes version: 3.12.0 Python version: 2.7.13 OS: Linux-4.9.87-linuxkit-aufs-x86_64-with-debian-stretch-sid Output dir: /under-test/output/2018_11_08_20_00_08_temp Mode: read error correction and assembling Debug mode is turned OFF Dataset parameters: Multi-cell mode (you should set '--sc' flag if input data was obtained with MDA (single-cell) technology or --meta flag if processing metagenomic dataset) Reads: Library number: 1, library type: paired-end orientation: fr left reads: ['/under-test/output/forward.fastq.gz_mapped.fq'] right reads: ['/under-test/output/reverse.fastq.gz_mapped.fq'] interlaced reads: not specified single reads: ['/under-test/output/forward.fastq.gz_combined.fq'] merged reads: not specified Read error correction parameters: Iterations: 1 PHRED offset will be auto-detected Corrected reads will be compressed Assembly parameters: k: automatic selection based on read length Repeat resolution is enabled Mismatch careful mode is turned ON MismatchCorrector will be used Coverage cutoff is turned OFF Other parameters: Dir for temp files: /under-test/output/2018_11_08_20_00_08_temp/tmp Threads: 4 Memory limit (in Gb): 1 ======= SPAdes pipeline started. Log can be found here: /under-test/output/2018_11_08_20_00_08_temp/spades.log ===== Read error correction started. == Running read error correction tool: /root/miniconda3/envs/seqsero/share/spades-3.12.0-1/bin/spades-hammer /under-test/output/2018_11_08_20_00_08_temp/corrected/configs/config.info 0:00:00.001 4M / 4M INFO General (main.cpp : 75) Starting BayesHammer, built from N/A, git revision N/A 0:00:00.001 4M / 4M INFO General (main.cpp : 76) Loading config from /under-test/output/2018_11_08_20_00_08_temp/corrected/configs/config.info 0:00:00.012 4M / 4M INFO General (main.cpp : 78) Maximum # of threads to use (adjusted due to OMP capabilities): 2 0:00:00.012 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1 Gb 0:00:00.012 4M / 4M INFO General (main.cpp : 86) Trying to determine PHRED offset 0:00:00.014 4M / 4M INFO General (main.cpp : 92) Determined value is 33 0:00:00.015 4M / 4M INFO General (hammer_tools.cpp : 36) Hamming graph threshold tau=1, k=21, subkmer positions = [ 0 10 ] 0:00:00.015 4M / 4M INFO General (main.cpp : 113) Size of aux. kmer data 24 bytes === ITERATION 0 begins === 0:00:00.019 4M / 4M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:00:00.019 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 32 files using 2 threads. This might take a while. 0:00:00.020 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1048576 0:00:00.020 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166016 Gb 0:00:00.020 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 696320 0:00:00.020 516M / 524M INFO K-mer Splitting (kmer_data.cpp : 97) Processing /under-test/output/forward.fastq.gz_mapped.fq 0:00:00.449 520M / 524M INFO K-mer Splitting (kmer_data.cpp : 97) Processing /under-test/output/reverse.fastq.gz_mapped.fq 0:00:00.838 520M / 524M INFO K-mer Splittin