Mercurial > repos > iuc > shovill
view test-data/shovill_std_log @ 9:ee17a294d3a3 draft default tip
planemo upload for repository https://github.com/galaxyproject/tools-iuc/tree/master/tools/shovill commit 0c2ed111d1186acce23eead97cf255c9af4efad1
| author | iuc |
|---|---|
| date | Thu, 12 Oct 2023 06:59:42 +0000 |
| parents | ad80238462c1 |
| children |
line wrap: on
line source
[shovill] Hello piemari [shovill] You ran: /home/piemari/apps/conda/envs/metaphlan/bin/shovill --outdir ../shovill_bam/ --cpus 8 --ram 4 --R1 ../mutant_R1.fastq --R2 ../mutant_R2.fastq --namefmt contig%05d --depth 100 --keepfiles --minlen 0 --mincov 2 --assembler spades --force [shovill] This is shovill 1.1.0 [shovill] Written by Torsten Seemann [shovill] Homepage is https://github.com/tseemann/shovill [shovill] Operating system is linux [shovill] Perl version is v5.32.1 [shovill] Machine has 32 CPU cores and 251.66 GB RAM [shovill] Using bwa - /home/piemari/apps/conda/envs/metaphlan/bin/bwa | Version: 0.7.17-r1188 [shovill] Using flash - /home/piemari/apps/conda/envs/metaphlan/bin/flash | FLASH v1.2.11 [shovill] Using java - /home/piemari/apps/conda/envs/metaphlan/bin/java | openjdk version "11.0.1" 2018-10-16 LTS [shovill] Using kmc - /home/piemari/apps/conda/envs/metaphlan/bin/kmc | K-Mer Counter (KMC) ver. 3.2.1 (2022-01-04) [shovill] Using lighter - /home/piemari/apps/conda/envs/metaphlan/bin/lighter | Lighter v1.1.2 [shovill] Using megahit - /home/piemari/apps/conda/envs/metaphlan/bin/megahit | MEGAHIT v1.2.9 [shovill] Using megahit_toolkit - /home/piemari/apps/conda/envs/metaphlan/bin/megahit_toolkit | v1.2.9 [shovill] Using pigz - /home/piemari/apps/conda/envs/metaphlan/bin/pigz | pigz 2.6 [shovill] Using pilon - /home/piemari/apps/conda/envs/metaphlan/bin/pilon | Pilon version 1.24 Thu Jan 28 13:00:45 2021 -0500 [shovill] Using samclip - /home/piemari/apps/conda/envs/metaphlan/bin/samclip | samclip 0.4.0 [shovill] Using samtools - /home/piemari/apps/conda/envs/metaphlan/bin/samtools | Version: 1.15 (using htslib 1.14) [shovill] Using seqtk - /home/piemari/apps/conda/envs/metaphlan/bin/seqtk | Version: 1.3-r106 [shovill] Using skesa - /home/piemari/apps/conda/envs/metaphlan/bin/skesa | SKESA 2.4.0 [shovill] Using spades.py - /home/piemari/apps/conda/envs/metaphlan/bin/spades.py | SPAdes genome assembler v3.14.1 [shovill] Using trimmomatic - /home/piemari/apps/conda/envs/metaphlan/bin/trimmomatic | 0.39 [shovill] Using velvetg - /home/piemari/apps/conda/envs/metaphlan/bin/velvetg | Version 1.2.10 [shovill] Using velveth - /home/piemari/apps/conda/envs/metaphlan/bin/velveth | Version 1.2.10 [shovill] Found spades version: 003014000 [shovill] Will use spades 003014000 options: --isolate and --merged [shovill] Forced overwrite of existing --outdir ../shovill_bam/ [shovill] Using tempdir: /tmp [shovill] Changing into folder: /home/piemari/shovill_bam [shovill] Collecting raw read statistics with 'seqtk' [shovill] Running: seqtk fqchk -q3 \/home\/piemari\/mutant_R1\.fastq >/tmp/1MILzK1fer 2>&1 | sed 's/^/[seqtk] /' | tee -a shovill.log [shovill] Read stats: max_len = 150 [shovill] Read stats: min_len = 150 [shovill] Read stats: total_bp = 300000 [shovill] Read stats: avg_len = 150 [shovill] Estimating genome size by counting unqiue 21-mers > frequency 10 [shovill] Running: kmc -sm -m2 -t8 -k21 -ci10 \/home\/piemari\/mutant_R1\.fastq /tmp/_n_4cOtiee/kmc /tmp/_n_4cOtiee 2>&1 | sed 's/^/[kmc] /' | tee -a shovill.log [kmc] ** [kmc] Stage 1: 0% Stage 1: 100% [kmc] Stage 2: 0% Stage 2: 84% Stage 2: 90% Stage 2: 94% Stage 2: 96% Stage 2: 98% Stage 2: 99% Stage 2: 100% [kmc] [kmc] [kmc] 1st stage: 0.08264s [kmc] 2nd stage: 0.104849s [kmc] 3rd stage: 0.002521s [kmc] Total : 0.19001s [kmc] Tmp size : 0MB [kmc] Tmp size strict memory : 0MB [kmc] Tmp total: 0MB [kmc] [kmc] Stats: [kmc] No. of k-mers below min. threshold : 34495 [kmc] No. of k-mers above max. threshold : 0 [kmc] No. of unique k-mers : 35683 [kmc] No. of unique counted k-mers : 1188 [kmc] Total no. of k-mers : 130000 [kmc] Total no. of reads : 1000 [kmc] Total no. of super-k-mers : 18576 [shovill] Using genome size 1188 bp [shovill] Estimated sequencing depth: 252 x [shovill] Subsampling reads by factor 0.397 to get from 252x to 100x [shovill] Running: seqtk sample \/home\/piemari\/mutant_R1\.fastq 0.397 | pigz --fast -c -p 8 > R1.sub.fq.gz 2>&1 | sed 's/^/[seqtk] /' | tee -a shovill.log [shovill] Running: seqtk sample \/home\/piemari\/mutant_R2\.fastq 0.397 | pigz --fast -c -p 8 > R2.sub.fq.gz 2>&1 | sed 's/^/[seqtk] /' | tee -a shovill.log [shovill] Appending -Xmx4g to _JAVA_OPTIONS [shovill] Running: ln -sf R1\.sub\.fq\.gz R1.fq.gz 2>&1 | sed 's/^/[ln] /' | tee -a shovill.log [shovill] Running: ln -sf R2\.sub\.fq\.gz R2.fq.gz 2>&1 | sed 's/^/[ln] /' | tee -a shovill.log [shovill] Average read length looks like 150 bp [shovill] Automatically setting --minlen to 75 [shovill] Setting k-mer range to (31 .. 112) [shovill] Estimated K-mers: 31 51 71 91 111 [kn=5, ks=20, kmin=31, kmax=112] [shovill] Using kmers: 31,51,71,91,111 [shovill] Correcting reads with 'Lighter' [shovill] Running: lighter -od . -r R1.fq.gz -r R2.fq.gz -K 32 1188 -t 8 -maxcor 1 2>&1 | sed 's/^/[lighter] /' | tee -a shovill.log [lighter] [2022-05-04 12:29:31] =============Start==================== [lighter] [2022-05-04 12:29:31] Scanning the input files to infer alpha(sampling rate) [lighter] [2022-05-04 12:29:31] Average coverage is 103.535 and alpha is 0.068 [lighter] [2022-05-04 12:29:31] Bad quality threshold is "1" [lighter] [2022-05-04 12:29:32] Finish sampling kmers [lighter] [2022-05-04 12:29:32] Bloom filter A's false positive rate: 0.264464 [lighter] [2022-05-04 12:29:32] Finish storing trusted kmers [lighter] [2022-05-04 12:29:32] Finish error correction [lighter] Processed 820 reads: [lighter] 48 are error-free [lighter] Corrected 1731 bases(2.242228 corrections for reads with errors) [lighter] Trimmed 0 reads with average trimmed bases 0.000000 [lighter] Discard 0 reads [shovill] Overlapping/stitching PE reads with 'FLASH' [shovill] Running: flash -m 20 -M 150 -d . -o flash -z -t 8 R1.cor.fq.gz R2.cor.fq.gz 2>&1 | sed 's/^//' | tee -a shovill.log [FLASH] Starting FLASH v1.2.11 [FLASH] Fast Length Adjustment of SHort reads [FLASH] [FLASH] Input files: [FLASH] R1.cor.fq.gz [FLASH] R2.cor.fq.gz [FLASH] [FLASH] Output files: [FLASH] ./flash.extendedFrags.fastq.gz [FLASH] ./flash.notCombined_1.fastq.gz [FLASH] ./flash.notCombined_2.fastq.gz [FLASH] ./flash.hist [FLASH] ./flash.histogram [FLASH] [FLASH] Parameters: [FLASH] Min overlap: 20 [FLASH] Max overlap: 150 [FLASH] Max mismatch density: 0.250000 [FLASH] Allow "outie" pairs: false [FLASH] Cap mismatch quals: false [FLASH] Combiner threads: 8 [FLASH] Input format: FASTQ, phred_offset=33 [FLASH] Output format: FASTQ, phred_offset=33, gzip [FLASH] [FLASH] Starting reader and writer threads [FLASH] Starting 8 combiner threads [FLASH] Processed 410 read pairs [FLASH] [FLASH] Read combination statistics: [FLASH] Total pairs: 410 [FLASH] Combined pairs: 387 [FLASH] Uncombined pairs: 23 [FLASH] Percent combined: 94.39% [FLASH] [FLASH] Writing histogram files. [FLASH] [FLASH] FLASH v1.2.11 complete! [FLASH] 0.022 seconds elapsed [shovill] Assembling reads with 'spades' [shovill] Running: spades.py -1 flash.notCombined_1.fastq.gz -2 flash.notCombined_2.fastq.gz --isolate --threads 8 --memory 4 -o spades --tmp-dir /tmp -k 31,51,71,91,111 --merged flash.extendedFrags.fastq.gz 2>&1 | sed 's/^/[spades] /' | tee -a shovill.log [spades] Command line: /home/piemari/apps/conda/envs/metaphlan/bin/spades.py -1 /home/piemari/shovill_bam/flash.notCombined_1.fastq.gz -2 /home/piemari/shovill_bam/flash.notCombined_2.fastq.gz --isolate --threads 8 --memory 4 -o /home/piemari/shovill_bam/spades --tmp-dir /tmp -k 31,51,71,91,111 --merged /home/piemari/shovill_bam/flash.extendedFrags.fastq.gz [spades] [spades] System information: [spades] SPAdes version: 3.14.1 [spades] Python version: 3.7.12 [spades] OS: Linux-3.10.0-1160.62.1.el7.x86_64-x86_64-with-centos-7.9.2009-Core [spades] [spades] Output dir: /home/piemari/shovill_bam/spades [spades] Mode: ONLY assembling (without read error correction) [spades] Debug mode is turned OFF [spades] [spades] Dataset parameters: [spades] Isolate mode [spades] Reads: [spades] Library number: 1, library type: paired-end [spades] orientation: fr [spades] left reads: ['/home/piemari/shovill_bam/flash.notCombined_1.fastq.gz'] [spades] right reads: ['/home/piemari/shovill_bam/flash.notCombined_2.fastq.gz'] [spades] interlaced reads: not specified [spades] single reads: not specified [spades] merged reads: ['/home/piemari/shovill_bam/flash.extendedFrags.fastq.gz'] [spades] Assembly parameters: [spades] k: [31, 51, 71, 91, 111] [spades] Repeat resolution is enabled [spades] Mismatch careful mode is turned OFF [spades] MismatchCorrector will be SKIPPED [spades] Coverage cutoff is turned OFF [spades] Other parameters: [spades] Dir for temp files: /tmp [spades] Threads: 8 [spades] Memory limit (in Gb): 4 [spades] [spades] [spades] ======= SPAdes pipeline started. Log can be found here: /home/piemari/shovill_bam/spades/spades.log [spades] [spades] /home/piemari/shovill_bam/flash.notCombined_1.fastq.gz: max reads length: 150 [spades] /home/piemari/shovill_bam/flash.notCombined_2.fastq.gz: max reads length: 150 [spades] Files with merged reads were ignored. [spades] [spades] Reads length: 150 [spades] [spades] [spades] ===== Before start started. [spades] [spades] [spades] ===== Assembling started. [spades] [spades] [spades] ===== K31 started. [spades] [spades] [spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K31/configs/config.info /home/piemari/shovill_bam/spades/K31/configs/isolate_mode.info [spades] [spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is tmp_contigs.fasta [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K31/configs/config.info [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K31/configs/isolate_mode.info [spades] 0:00:00.000 4M / 10M INFO General (memory_limit.cpp : 49) Memory limit set to 4 Gb [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 85) Starting SPAdes, built from N/A, git revision N/A [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 86) Maximum k-mer length: 128 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 87) Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=31 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 88) Maximum # of threads to use (adjusted due to OMP capabilities): 8 [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 194) SPAdes started [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 201) Starting from stage: read_conversion [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 207) Two-step RR enabled: 0 [spades] 0:00:00.000 4M / 10M INFO StageManager (stage.cpp : 166) STAGE == Binary Read Conversion [spades] 0:00:00.002 4M / 12M INFO General (read_converter.cpp : 72) Converting reads to binary format for library #0 (takes a while) [spades] 0:00:00.002 4M / 12M INFO General (read_converter.cpp : 73) Converting paired reads [spades] 0:00:00.009 71M / 71M INFO General (binary_converter.cpp : 111) 23 reads written [spades] 0:00:00.009 47M / 47M INFO General (read_converter.cpp : 81) Converting single reads [spades] 0:00:00.011 57M / 57M INFO General (binary_converter.cpp : 111) 0 reads written [spades] 0:00:00.011 57M / 57M INFO General (read_converter.cpp : 87) Converting merged reads [spades] 0:00:00.017 77M / 77M INFO General (binary_converter.cpp : 111) 387 reads written [spades] 0:00:00.022 17M / 40M INFO StageManager (stage.cpp : 166) STAGE == de Bruijn graph construction [spades] 0:00:00.026 17M / 40M INFO General (construction.cpp : 150) Max read length 280 [spades] 0:00:00.026 17M / 40M INFO General (construction.cpp : 153) Max read length without merged 150 [spades] 0:00:00.026 17M / 40M INFO General (construction.cpp : 156) Average read length 193.032 [spades] 0:00:00.026 17M / 40M INFO General (stage.cpp : 113) PROCEDURE == k+1-mer counting [spades] 0:00:00.026 17M / 40M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 8 threads. This might take a while. [spades] 0:00:00.026 17M / 40M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.027 17M / 40M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166615 Gb [spades] 0:00:00.027 17M / 40M INFO General (kmer_splitters.hpp : 97) Using cell size of 349417 [spades] 0:00:00.100 71M / 560M INFO General (kmer_splitters.hpp : 293) Used 866 reads [spades] 0:00:00.100 71M / 560M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.111 71M / 560M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 7283 kmers in total. [spades] 0:00:00.111 71M / 560M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.114 71M / 560M INFO General (stage.cpp : 113) PROCEDURE == Extension index construction [spades] 0:00:00.114 71M / 560M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.114 71M / 560M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.115 71M / 560M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.115 71M / 560M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166468 Gb [spades] 0:00:00.115 71M / 560M INFO General (kmer_splitters.hpp : 97) Using cell size of 174554 [spades] 0:00:00.188 2G / 2G INFO General (kmer_splitters.hpp : 364) Processed 7283 kmers [spades] 0:00:00.188 2G / 2G INFO General (kmer_splitters.hpp : 369) Used 7283 kmers. [spades] 0:00:00.212 85M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.236 85M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 7222 kmers in total. [spades] 0:00:00.236 85M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.241 85M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.264 86M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.266 86M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 12384 bytes occupied (13.7181 bits per kmer). [spades] 0:00:00.266 86M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers [spades] 0:00:00.273 86M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. [spades] 0:00:00.274 86M / 2G INFO General (stage.cpp : 113) PROCEDURE == Early tip clipping [spades] 0:00:00.274 86M / 2G INFO General (construction.cpp : 293) Early tip clipper length bound set as (RL - K) [spades] 0:00:00.274 86M / 2G INFO Early tip clipping (early_simplification.hpp : 28) Early tip clipping [spades] 0:00:00.279 86M / 2G INFO Early tip clipping (early_simplification.hpp : 63) #tipped junctions: 96 [spades] 0:00:00.284 86M / 2G INFO Early tip clipping (early_simplification.hpp : 74) Clipped tips: 97 [spades] 0:00:00.284 86M / 2G INFO Early tip clipping (early_simplification.hpp : 30) 2642 32-mers were removed by early tip clipper [spades] 0:00:00.285 86M / 2G INFO General (stage.cpp : 113) PROCEDURE == Condensing graph [spades] 0:00:00.285 86M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths [spades] 0:00:00.287 86M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 373) Extracting unbranching paths finished. 186 sequences extracted [spades] 0:00:00.288 86M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 309) Collecting perfect loops [spades] 0:00:00.289 86M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 342) Collecting perfect loops finished. 0 loops collected [spades] 0:00:00.290 86M / 2G INFO General (stage.cpp : 113) PROCEDURE == Filling coverage indices (PHM) [spades] 0:00:00.290 86M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.290 86M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.301 87M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 7864 bytes occupied (8.6382 bits per kmer). [spades] 0:00:00.301 87M / 2G INFO General (construction.cpp : 429) Collecting k-mer coverage information from reads, this takes a while. [spades] 0:00:00.310 87M / 2G INFO General (construction.cpp : 549) Filling coverage and flanking coverage from PHM [spades] 0:00:00.314 87M / 2G INFO StageManager (stage.cpp : 166) STAGE == EC Threshold Finding [spades] 0:00:00.314 87M / 2G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 2 [spades] 0:00:00.315 87M / 2G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 60 [spades] 0:00:00.315 87M / 2G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 60. Coverage mad: 7.413 [spades] 0:00:00.315 87M / 2G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model [spades] 0:00:00.324 87M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 [spades] 0:00:00.349 87M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 [spades] 0:00:00.414 87M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 [spades] 0:00:00.501 87M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16 [spades] 0:00:00.540 87M / 2G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 56.9644. Fitted coverage std. dev: 9.10691 [spades] 0:00:00.540 87M / 2G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1 [spades] 0:00:00.541 87M / 2G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 39 [spades] 0:00:00.541 87M / 2G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 29 [spades] 0:00:00.541 87M / 2G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 1104 [spades] 0:00:00.541 87M / 2G INFO General (genomic_info_filler.cpp : 53) Mean coverage was calculated as 56.9644 [spades] 0:00:00.541 87M / 2G INFO General (genomic_info_filler.cpp : 68) EC coverage threshold value was calculated as 29 [spades] 0:00:00.542 87M / 2G INFO General (genomic_info_filler.cpp : 69) Trusted kmer low bound: 0 [spades] 0:00:00.542 87M / 2G INFO StageManager (stage.cpp : 166) STAGE == Raw Simplification [spades] 0:00:00.542 87M / 2G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning [spades] 0:00:00.542 87M / 2G INFO General (graph_simplification.hpp : 671) Flanking coverage based disconnection disabled [spades] 0:00:00.542 87M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover [spades] 0:00:00.545 87M / 2G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times [spades] 0:00:00.545 87M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification [spades] 0:00:00.546 87M / 2G INFO General (simplification.cpp : 383) Graph simplification started [spades] 0:00:00.546 87M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.546 87M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 1 [spades] 0:00:00.546 87M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.550 87M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.550 87M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.557 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 60 times [spades] 0:00:00.557 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.559 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 3 times [spades] 0:00:00.560 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 2 [spades] 0:00:00.560 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.560 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.561 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.561 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.561 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.561 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.562 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 3 [spades] 0:00:00.562 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.562 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.562 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.562 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.563 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.563 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.563 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 4 [spades] 0:00:00.563 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.563 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.564 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.564 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.564 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.564 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.564 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 5 [spades] 0:00:00.564 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.565 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.565 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.565 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.565 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.565 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.566 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 6 [spades] 0:00:00.566 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.566 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.566 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.566 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.567 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.567 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.567 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 7 [spades] 0:00:00.567 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.567 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.568 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.568 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.568 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.568 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.568 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 8 [spades] 0:00:00.568 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.569 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.569 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.569 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.569 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.569 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.570 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 9 [spades] 0:00:00.570 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.570 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.570 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.570 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.571 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.571 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.571 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 10 [spades] 0:00:00.571 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.571 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.571 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.572 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.572 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.572 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.572 84M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 11 [spades] 0:00:00.572 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.575 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.575 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.576 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.576 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.576 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.576 84M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification Cleanup [spades] 0:00:00.576 84M / 2G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification [spades] 0:00:00.577 84M / 2G INFO General (graph_simplification.hpp : 456) Disconnection of relatively low covered edges disabled [spades] 0:00:00.577 84M / 2G INFO General (graph_simplification.hpp : 493) Complex tip clipping disabled [spades] 0:00:00.577 84M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.577 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.578 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.578 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.578 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.578 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.579 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.579 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.579 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.579 84M / 2G INFO General (simplification.cpp : 343) Disrupting self-conjugate edges [spades] 0:00:00.579 84M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges [spades] 0:00:00.580 84M / 2G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 1 times [spades] 0:00:00.580 84M / 2G INFO General (simplification.cpp : 496) Counting average coverage [spades] 0:00:00.580 84M / 2G INFO General (simplification.cpp : 502) Average coverage = 55.1872 [spades] 0:00:00.580 84M / 2G INFO StageManager (stage.cpp : 166) STAGE == Contig Output [spades] 0:00:00.583 84M / 2G INFO General (read_converter.cpp : 102) Outputting contigs to /home/piemari/shovill_bam/spades/K31/simplified_contigs [spades] 0:00:00.585 84M / 2G INFO General (binary_converter.cpp : 111) 1 reads written [spades] 0:00:00.589 84M / 2G INFO General (pipeline.cpp : 259) SPAdes finished [spades] 0:00:00.590 84M / 2G INFO General (main.cpp : 107) Assembling time: 0 hours 0 minutes 0 seconds [spades] [spades] ===== K31 finished. [spades] [spades] [spades] ===== K51 started. [spades] [spades] [spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K51/configs/config.info /home/piemari/shovill_bam/spades/K51/configs/isolate_mode.info [spades] [spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is /home/piemari/shovill_bam/spades/K31/simplified_contigs [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K51/configs/config.info [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K51/configs/isolate_mode.info [spades] 0:00:00.000 4M / 10M INFO General (memory_limit.cpp : 49) Memory limit set to 4 Gb [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 85) Starting SPAdes, built from N/A, git revision N/A [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 86) Maximum k-mer length: 128 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 87) Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=51 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 88) Maximum # of threads to use (adjusted due to OMP capabilities): 8 [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 194) SPAdes started [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 201) Starting from stage: read_conversion [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 207) Two-step RR enabled: 0 [spades] 0:00:00.000 4M / 10M INFO StageManager (stage.cpp : 166) STAGE == Binary Read Conversion [spades] 0:00:00.001 4M / 12M INFO General (read_converter.cpp : 53) Binary reads detected [spades] 0:00:00.002 4M / 14M INFO StageManager (stage.cpp : 166) STAGE == de Bruijn graph construction [spades] 0:00:00.002 4M / 14M INFO General (construction.cpp : 115) Contigs from previous K will be used: /home/piemari/shovill_bam/spades/K31/simplified_contigs [spades] 0:00:00.007 4M / 14M INFO General (construction.cpp : 150) Max read length 280 [spades] 0:00:00.007 4M / 14M INFO General (construction.cpp : 153) Max read length without merged 150 [spades] 0:00:00.007 4M / 14M INFO General (construction.cpp : 156) Average read length 193.032 [spades] 0:00:00.007 4M / 14M INFO General (stage.cpp : 113) PROCEDURE == k+1-mer counting [spades] 0:00:00.007 4M / 14M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 8 threads. This might take a while. [spades] 0:00:00.007 4M / 14M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.007 4M / 14M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166632 Gb [spades] 0:00:00.007 4M / 14M INFO General (kmer_splitters.hpp : 97) Using cell size of 174726 [spades] 0:00:00.085 84M / 556M INFO General (kmer_splitters.hpp : 293) Used 868 reads [spades] 0:00:00.085 84M / 556M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.102 84M / 556M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8238 kmers in total. [spades] 0:00:00.102 84M / 556M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.106 84M / 556M INFO General (stage.cpp : 113) PROCEDURE == Extension index construction [spades] 0:00:00.106 84M / 556M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.106 84M / 556M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.106 84M / 556M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.106 84M / 556M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166509 Gb [spades] 0:00:00.107 84M / 556M INFO General (kmer_splitters.hpp : 97) Using cell size of 87298 [spades] 0:00:00.181 2G / 2G INFO General (kmer_splitters.hpp : 364) Processed 8238 kmers [spades] 0:00:00.181 2G / 2G INFO General (kmer_splitters.hpp : 369) Used 8238 kmers. [spades] 0:00:00.203 97M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.220 97M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8201 kmers in total. [spades] 0:00:00.221 97M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.226 97M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.252 92M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.253 92M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 12872 bytes occupied (12.5565 bits per kmer). [spades] 0:00:00.254 92M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers [spades] 0:00:00.257 92M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. [spades] 0:00:00.258 92M / 2G INFO General (stage.cpp : 113) PROCEDURE == Early tip clipping [spades] 0:00:00.258 92M / 2G INFO General (construction.cpp : 293) Early tip clipper length bound set as (RL - K) [spades] 0:00:00.259 92M / 2G INFO Early tip clipping (early_simplification.hpp : 28) Early tip clipping [spades] 0:00:00.263 92M / 2G INFO Early tip clipping (early_simplification.hpp : 63) #tipped junctions: 115 [spades] 0:00:00.268 92M / 2G INFO Early tip clipping (early_simplification.hpp : 74) Clipped tips: 116 [spades] 0:00:00.268 92M / 2G INFO Early tip clipping (early_simplification.hpp : 30) 3952 52-mers were removed by early tip clipper [spades] 0:00:00.268 92M / 2G INFO General (stage.cpp : 113) PROCEDURE == Condensing graph [spades] 0:00:00.269 92M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths [spades] 0:00:00.272 92M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 373) Extracting unbranching paths finished. 118 sequences extracted [spades] 0:00:00.273 92M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 309) Collecting perfect loops [spades] 0:00:00.274 92M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 342) Collecting perfect loops finished. 0 loops collected [spades] 0:00:00.274 92M / 2G INFO General (stage.cpp : 113) PROCEDURE == Filling coverage indices (PHM) [spades] 0:00:00.275 92M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.275 92M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.286 92M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 8280 bytes occupied (8.04079 bits per kmer). [spades] 0:00:00.286 92M / 2G INFO General (construction.cpp : 429) Collecting k-mer coverage information from reads, this takes a while. [spades] 0:00:00.294 92M / 2G INFO General (construction.cpp : 549) Filling coverage and flanking coverage from PHM [spades] 0:00:00.297 92M / 2G INFO StageManager (stage.cpp : 166) STAGE == EC Threshold Finding [spades] 0:00:00.297 92M / 2G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 2 [spades] 0:00:00.297 92M / 2G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 51 [spades] 0:00:00.298 92M / 2G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 51. Coverage mad: 7.413 [spades] 0:00:00.298 92M / 2G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model [spades] 0:00:00.306 92M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 [spades] 0:00:00.326 92M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 [spades] 0:00:00.371 92M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 [spades] 0:00:00.392 92M / 2G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 48.7323. Fitted coverage std. dev: 7.8967 [spades] 0:00:00.392 92M / 2G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1 [spades] 0:00:00.393 92M / 2G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 33 [spades] 0:00:00.393 92M / 2G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 25 [spades] 0:00:00.393 92M / 2G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 1099 [spades] 0:00:00.393 92M / 2G INFO General (genomic_info_filler.cpp : 53) Mean coverage was calculated as 48.7323 [spades] 0:00:00.393 92M / 2G INFO General (genomic_info_filler.cpp : 68) EC coverage threshold value was calculated as 25 [spades] 0:00:00.394 92M / 2G INFO General (genomic_info_filler.cpp : 69) Trusted kmer low bound: 0 [spades] 0:00:00.394 92M / 2G INFO StageManager (stage.cpp : 166) STAGE == Raw Simplification [spades] 0:00:00.394 92M / 2G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning [spades] 0:00:00.394 92M / 2G INFO General (graph_simplification.hpp : 671) Flanking coverage based disconnection disabled [spades] 0:00:00.394 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover [spades] 0:00:00.397 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times [spades] 0:00:00.397 92M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification [spades] 0:00:00.398 92M / 2G INFO General (simplification.cpp : 383) Graph simplification started [spades] 0:00:00.398 92M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.398 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 1 [spades] 0:00:00.399 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.399 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.399 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.401 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 40 times [spades] 0:00:00.402 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.402 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.402 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 2 [spades] 0:00:00.403 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.403 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.403 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.404 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.404 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.404 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.405 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 3 [spades] 0:00:00.405 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.405 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.405 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.405 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.405 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.406 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.406 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 4 [spades] 0:00:00.406 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.406 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.406 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.406 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.407 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.407 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.407 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 5 [spades] 0:00:00.407 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.407 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.407 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.408 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.408 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.408 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.408 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 6 [spades] 0:00:00.408 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.408 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.408 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.409 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.409 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.409 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.409 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 7 [spades] 0:00:00.409 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.409 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.410 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.410 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.410 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.410 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.410 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 8 [spades] 0:00:00.410 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.411 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.411 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.411 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.411 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.411 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.411 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 9 [spades] 0:00:00.412 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.412 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.412 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.412 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.412 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.412 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.413 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 10 [spades] 0:00:00.413 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.413 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.413 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.413 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.413 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.413 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.414 92M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 11 [spades] 0:00:00.414 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.416 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.416 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.416 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.417 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.417 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.417 92M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification Cleanup [spades] 0:00:00.418 92M / 2G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification [spades] 0:00:00.418 92M / 2G INFO General (graph_simplification.hpp : 456) Disconnection of relatively low covered edges disabled [spades] 0:00:00.418 92M / 2G INFO General (graph_simplification.hpp : 493) Complex tip clipping disabled [spades] 0:00:00.419 92M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.419 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.419 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.420 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.420 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.420 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.421 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.421 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.421 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.421 92M / 2G INFO General (simplification.cpp : 343) Disrupting self-conjugate edges [spades] 0:00:00.422 92M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges [spades] 0:00:00.422 92M / 2G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 2 times [spades] 0:00:00.422 92M / 2G INFO General (simplification.cpp : 496) Counting average coverage [spades] 0:00:00.423 92M / 2G INFO General (simplification.cpp : 502) Average coverage = 47.8689 [spades] 0:00:00.423 92M / 2G INFO StageManager (stage.cpp : 166) STAGE == Contig Output [spades] 0:00:00.424 92M / 2G INFO General (read_converter.cpp : 102) Outputting contigs to /home/piemari/shovill_bam/spades/K51/simplified_contigs [spades] 0:00:00.426 92M / 2G INFO General (binary_converter.cpp : 111) 1 reads written [spades] 0:00:00.433 92M / 2G INFO General (pipeline.cpp : 259) SPAdes finished [spades] 0:00:00.433 92M / 2G INFO General (main.cpp : 107) Assembling time: 0 hours 0 minutes 0 seconds [spades] [spades] ===== K51 finished. [spades] [spades] [spades] ===== K71 started. [spades] [spades] [spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K71/configs/config.info /home/piemari/shovill_bam/spades/K71/configs/isolate_mode.info [spades] [spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is /home/piemari/shovill_bam/spades/K51/simplified_contigs [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K71/configs/config.info [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K71/configs/isolate_mode.info [spades] 0:00:00.000 4M / 10M INFO General (memory_limit.cpp : 49) Memory limit set to 4 Gb [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 85) Starting SPAdes, built from N/A, git revision N/A [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 86) Maximum k-mer length: 128 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 87) Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=71 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 88) Maximum # of threads to use (adjusted due to OMP capabilities): 8 [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 194) SPAdes started [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 201) Starting from stage: read_conversion [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 207) Two-step RR enabled: 0 [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 218) Will need read mapping, kmer mapper will be attached [spades] 0:00:00.000 4M / 10M INFO StageManager (stage.cpp : 166) STAGE == Binary Read Conversion [spades] 0:00:00.001 4M / 12M INFO General (read_converter.cpp : 53) Binary reads detected [spades] 0:00:00.001 4M / 14M INFO StageManager (stage.cpp : 166) STAGE == de Bruijn graph construction [spades] 0:00:00.001 4M / 14M INFO General (construction.cpp : 115) Contigs from previous K will be used: /home/piemari/shovill_bam/spades/K51/simplified_contigs [spades] 0:00:00.006 4M / 14M INFO General (construction.cpp : 150) Max read length 280 [spades] 0:00:00.006 4M / 14M INFO General (construction.cpp : 153) Max read length without merged 150 [spades] 0:00:00.006 4M / 14M INFO General (construction.cpp : 156) Average read length 193.032 [spades] 0:00:00.006 4M / 14M INFO General (stage.cpp : 113) PROCEDURE == k+1-mer counting [spades] 0:00:00.006 4M / 14M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 8 threads. This might take a while. [spades] 0:00:00.007 4M / 14M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.007 4M / 14M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166632 Gb [spades] 0:00:00.007 4M / 14M INFO General (kmer_splitters.hpp : 97) Using cell size of 116484 [spades] 0:00:00.088 81M / 554M INFO General (kmer_splitters.hpp : 293) Used 868 reads [spades] 0:00:00.088 81M / 554M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.100 83M / 554M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8725 kmers in total. [spades] 0:00:00.100 83M / 554M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.104 83M / 554M INFO General (stage.cpp : 113) PROCEDURE == Extension index construction [spades] 0:00:00.104 83M / 554M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.104 83M / 554M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.104 83M / 554M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.104 83M / 554M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166542 Gb [spades] 0:00:00.104 83M / 554M INFO General (kmer_splitters.hpp : 97) Using cell size of 58210 [spades] 0:00:00.177 2G / 2G INFO General (kmer_splitters.hpp : 364) Processed 8725 kmers [spades] 0:00:00.177 2G / 2G INFO General (kmer_splitters.hpp : 369) Used 8725 kmers. [spades] 0:00:00.200 89M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.218 89M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8713 kmers in total. [spades] 0:00:00.218 89M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.224 89M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.249 87M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.251 87M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 13120 bytes occupied (12.0464 bits per kmer). [spades] 0:00:00.251 87M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers [spades] 0:00:00.254 87M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. [spades] 0:00:00.255 87M / 2G INFO General (stage.cpp : 113) PROCEDURE == Condensing graph [spades] 0:00:00.255 87M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths [spades] 0:00:00.260 87M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 373) Extracting unbranching paths finished. 308 sequences extracted [spades] 0:00:00.266 87M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 309) Collecting perfect loops [spades] 0:00:00.271 87M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 342) Collecting perfect loops finished. 0 loops collected [spades] 0:00:00.280 87M / 2G INFO General (stage.cpp : 113) PROCEDURE == Filling coverage indices (PHM) [spades] 0:00:00.281 87M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.281 87M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.294 87M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 8536 bytes occupied (7.8267 bits per kmer). [spades] 0:00:00.294 87M / 2G INFO General (construction.cpp : 429) Collecting k-mer coverage information from reads, this takes a while. [spades] 0:00:00.300 87M / 2G INFO General (construction.cpp : 549) Filling coverage and flanking coverage from PHM [spades] 0:00:00.307 87M / 2G INFO StageManager (stage.cpp : 166) STAGE == EC Threshold Finding [spades] 0:00:00.308 87M / 2G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 2 [spades] 0:00:00.308 87M / 2G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 44 [spades] 0:00:00.308 87M / 2G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 44. Coverage mad: 7.413 [spades] 0:00:00.308 87M / 2G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model [spades] 0:00:00.315 87M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 [spades] 0:00:00.334 87M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 [spades] 0:00:00.377 87M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 [spades] 0:00:00.421 87M / 2G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 40.9755. Fitted coverage std. dev: 6.3525 [spades] 0:00:00.421 87M / 2G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1 [spades] 0:00:00.421 87M / 2G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 28 [spades] 0:00:00.421 87M / 2G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 21 [spades] 0:00:00.422 87M / 2G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 1088 [spades] 0:00:00.422 87M / 2G INFO General (genomic_info_filler.cpp : 53) Mean coverage was calculated as 40.9755 [spades] 0:00:00.422 87M / 2G INFO General (genomic_info_filler.cpp : 68) EC coverage threshold value was calculated as 21 [spades] 0:00:00.422 87M / 2G INFO General (genomic_info_filler.cpp : 69) Trusted kmer low bound: 0 [spades] 0:00:00.423 87M / 2G INFO StageManager (stage.cpp : 166) STAGE == Gap Closer [spades] 0:00:00.423 87M / 2G INFO General (graph_pack.hpp : 105) Index refill [spades] 0:00:00.423 87M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.423 87M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.424 87M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.424 87M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166486 Gb [spades] 0:00:00.424 87M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 58191 [spades] 0:00:00.513 2G / 2G INFO General (edge_index_builders.hpp : 82) Used 616 sequences. [spades] 0:00:00.531 94M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.562 94M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8725 kmers in total. [spades] 0:00:00.563 94M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.568 94M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.586 89M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.588 89M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 13104 bytes occupied (12.0151 bits per kmer). [spades] 0:00:00.588 89M / 2G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. [spades] 0:00:00.592 89M / 2G INFO General (edge_index.hpp : 92) Index refilled [spades] 0:00:00.595 89M / 2G INFO General (gap_closer.cpp : 147) Preparing shift maps [spades] 0:00:00.596 89M / 2G INFO General (gap_closer.cpp : 107) Processing paired reads (takes a while) [spades] 0:00:00.598 89M / 2G INFO General (gap_closer.cpp : 126) Used 23 paired reads [spades] 0:00:00.598 89M / 2G INFO General (gap_closer.cpp : 128) Merging paired indices [spades] 0:00:00.598 89M / 2G INFO GapCloser (gap_closer.cpp : 332) Closing short gaps [spades] 0:00:00.599 89M / 2G INFO GapCloser (gap_closer.cpp : 364) Closing short gaps complete: filled 0 gaps after checking 0 candidates [spades] 0:00:00.599 89M / 2G INFO StageManager (stage.cpp : 166) STAGE == Raw Simplification [spades] 0:00:00.599 89M / 2G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning [spades] 0:00:00.600 89M / 2G INFO General (graph_simplification.hpp : 671) Flanking coverage based disconnection disabled [spades] 0:00:00.600 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover [spades] 0:00:00.600 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times [spades] 0:00:00.600 89M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification [spades] 0:00:00.601 89M / 2G INFO General (simplification.cpp : 383) Graph simplification started [spades] 0:00:00.601 89M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.601 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 1 [spades] 0:00:00.601 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.603 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 128 times [spades] 0:00:00.603 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.607 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 19 times [spades] 0:00:00.607 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.609 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.609 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 2 [spades] 0:00:00.609 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.610 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.610 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.610 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.610 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.611 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.611 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 3 [spades] 0:00:00.611 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.611 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.611 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.612 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.612 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.612 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.612 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 4 [spades] 0:00:00.612 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.612 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.613 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.613 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.613 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.613 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.613 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 5 [spades] 0:00:00.613 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.614 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.614 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.614 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.614 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.614 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.614 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 6 [spades] 0:00:00.615 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.615 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.615 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.615 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.615 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.615 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.616 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 7 [spades] 0:00:00.616 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.616 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.616 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.616 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.617 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.617 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.617 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 8 [spades] 0:00:00.617 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.617 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.617 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.618 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.618 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.618 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.618 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 9 [spades] 0:00:00.618 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.618 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.619 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.619 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.619 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.619 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.619 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 10 [spades] 0:00:00.619 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.620 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.620 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.620 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.620 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.620 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.620 89M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 11 [spades] 0:00:00.621 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.623 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.623 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.623 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.623 89M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.624 89M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.624 89M / 2G INFO StageManager (stage.cpp : 166) STAGE == Gap Closer [spades] 0:00:00.624 89M / 2G INFO General (graph_pack.hpp : 105) Index refill [spades] 0:00:00.625 89M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.625 89M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.625 89M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.626 89M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166471 Gb [spades] 0:00:00.626 89M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 58185 [spades] 0:00:00.681 2G / 2G INFO General (edge_index_builders.hpp : 82) Used 14 sequences. [spades] 0:00:00.688 100M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.704 100M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 1720 kmers in total. [spades] 0:00:00.704 100M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.709 100M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.728 100M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.729 100M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 10088 bytes occupied (46.9209 bits per kmer). [spades] 0:00:00.730 100M / 2G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. [spades] 0:00:00.733 100M / 2G INFO General (edge_index.hpp : 92) Index refilled [spades] 0:00:00.735 100M / 2G INFO General (gap_closer.cpp : 147) Preparing shift maps [spades] 0:00:00.735 100M / 2G INFO General (gap_closer.cpp : 107) Processing paired reads (takes a while) [spades] 0:00:00.738 100M / 2G INFO General (gap_closer.cpp : 126) Used 23 paired reads [spades] 0:00:00.739 100M / 2G INFO General (gap_closer.cpp : 128) Merging paired indices [spades] 0:00:00.739 100M / 2G INFO GapCloser (gap_closer.cpp : 332) Closing short gaps [spades] 0:00:00.739 100M / 2G INFO GapCloser (gap_closer.cpp : 364) Closing short gaps complete: filled 0 gaps after checking 0 candidates [spades] 0:00:00.743 100M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification Cleanup [spades] 0:00:00.744 100M / 2G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification [spades] 0:00:00.744 100M / 2G INFO General (graph_simplification.hpp : 456) Disconnection of relatively low covered edges disabled [spades] 0:00:00.744 100M / 2G INFO General (graph_simplification.hpp : 493) Complex tip clipping disabled [spades] 0:00:00.744 100M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.745 100M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.748 100M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.748 100M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.753 100M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.753 100M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.760 100M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.761 100M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.766 100M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.766 100M / 2G INFO General (simplification.cpp : 343) Disrupting self-conjugate edges [spades] 0:00:00.766 100M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges [spades] 0:00:00.770 100M / 2G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 6 times [spades] 0:00:00.770 100M / 2G INFO General (simplification.cpp : 496) Counting average coverage [spades] 0:00:00.770 100M / 2G INFO General (simplification.cpp : 502) Average coverage = 39.6025 [spades] 0:00:00.770 100M / 2G INFO StageManager (stage.cpp : 166) STAGE == Contig Output [spades] 0:00:00.771 100M / 2G INFO General (read_converter.cpp : 102) Outputting contigs to /home/piemari/shovill_bam/spades/K71/simplified_contigs [spades] 0:00:00.775 100M / 2G INFO General (binary_converter.cpp : 111) 1 reads written [spades] 0:00:00.780 100M / 2G INFO General (pipeline.cpp : 259) SPAdes finished [spades] 0:00:00.781 100M / 2G INFO General (main.cpp : 107) Assembling time: 0 hours 0 minutes 0 seconds [spades] [spades] ===== K71 finished. [spades] [spades] [spades] ===== K91 started. [spades] [spades] [spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K91/configs/config.info /home/piemari/shovill_bam/spades/K91/configs/isolate_mode.info [spades] [spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is /home/piemari/shovill_bam/spades/K71/simplified_contigs [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K91/configs/config.info [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K91/configs/isolate_mode.info [spades] 0:00:00.000 4M / 10M INFO General (memory_limit.cpp : 49) Memory limit set to 4 Gb [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 85) Starting SPAdes, built from N/A, git revision N/A [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 86) Maximum k-mer length: 128 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 87) Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=91 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 88) Maximum # of threads to use (adjusted due to OMP capabilities): 8 [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 194) SPAdes started [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 201) Starting from stage: read_conversion [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 207) Two-step RR enabled: 0 [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 218) Will need read mapping, kmer mapper will be attached [spades] 0:00:00.000 4M / 10M INFO StageManager (stage.cpp : 166) STAGE == Binary Read Conversion [spades] 0:00:00.002 4M / 12M INFO General (read_converter.cpp : 53) Binary reads detected [spades] 0:00:00.003 4M / 16M INFO StageManager (stage.cpp : 166) STAGE == de Bruijn graph construction [spades] 0:00:00.003 4M / 16M INFO General (construction.cpp : 115) Contigs from previous K will be used: /home/piemari/shovill_bam/spades/K71/simplified_contigs [spades] 0:00:00.014 4M / 16M INFO General (construction.cpp : 150) Max read length 280 [spades] 0:00:00.014 4M / 16M INFO General (construction.cpp : 153) Max read length without merged 150 [spades] 0:00:00.014 4M / 16M INFO General (construction.cpp : 156) Average read length 193.032 [spades] 0:00:00.014 4M / 16M INFO General (stage.cpp : 113) PROCEDURE == k+1-mer counting [spades] 0:00:00.014 4M / 16M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 8 threads. This might take a while. [spades] 0:00:00.014 4M / 16M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.014 4M / 16M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166632 Gb [spades] 0:00:00.015 4M / 16M INFO General (kmer_splitters.hpp : 97) Using cell size of 116484 [spades] 0:00:00.092 83M / 554M INFO General (kmer_splitters.hpp : 293) Used 868 reads [spades] 0:00:00.092 83M / 554M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.104 83M / 554M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8793 kmers in total. [spades] 0:00:00.105 83M / 554M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.108 83M / 554M INFO General (stage.cpp : 113) PROCEDURE == Extension index construction [spades] 0:00:00.108 83M / 554M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.108 83M / 554M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.108 83M / 554M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.108 83M / 554M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166534 Gb [spades] 0:00:00.108 83M / 554M INFO General (kmer_splitters.hpp : 97) Using cell size of 58208 [spades] 0:00:00.181 2G / 2G INFO General (kmer_splitters.hpp : 364) Processed 8793 kmers [spades] 0:00:00.181 2G / 2G INFO General (kmer_splitters.hpp : 369) Used 8793 kmers. [spades] 0:00:00.204 98M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.221 98M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8798 kmers in total. [spades] 0:00:00.221 98M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.227 98M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.250 96M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.252 96M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 13136 bytes occupied (11.9445 bits per kmer). [spades] 0:00:00.252 96M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers [spades] 0:00:00.256 96M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. [spades] 0:00:00.256 96M / 2G INFO General (stage.cpp : 113) PROCEDURE == Condensing graph [spades] 0:00:00.256 96M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths [spades] 0:00:00.262 96M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 373) Extracting unbranching paths finished. 294 sequences extracted [spades] 0:00:00.263 96M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 309) Collecting perfect loops [spades] 0:00:00.264 96M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 342) Collecting perfect loops finished. 0 loops collected [spades] 0:00:00.265 96M / 2G INFO General (stage.cpp : 113) PROCEDURE == Filling coverage indices (PHM) [spades] 0:00:00.265 96M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.265 96M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.276 97M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 8576 bytes occupied (7.80257 bits per kmer). [spades] 0:00:00.276 97M / 2G INFO General (construction.cpp : 429) Collecting k-mer coverage information from reads, this takes a while. [spades] 0:00:00.280 97M / 2G INFO General (construction.cpp : 549) Filling coverage and flanking coverage from PHM [spades] 0:00:00.282 97M / 2G INFO StageManager (stage.cpp : 166) STAGE == EC Threshold Finding [spades] 0:00:00.282 97M / 2G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 2 [spades] 0:00:00.283 97M / 2G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 32 [spades] 0:00:00.283 97M / 2G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 33. Coverage mad: 5.9304 [spades] 0:00:00.283 97M / 2G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model [spades] 0:00:00.289 97M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 [spades] 0:00:00.304 97M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 [spades] 0:00:00.356 97M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 [spades] 0:00:00.392 97M / 2G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 33.4369. Fitted coverage std. dev: 4.99367 [spades] 0:00:00.392 97M / 2G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 1 [spades] 0:00:00.393 97M / 2G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 23 [spades] 0:00:00.393 97M / 2G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 17 [spades] 0:00:00.393 97M / 2G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 1078 [spades] 0:00:00.393 97M / 2G INFO General (genomic_info_filler.cpp : 53) Mean coverage was calculated as 33.4369 [spades] 0:00:00.393 97M / 2G INFO General (genomic_info_filler.cpp : 68) EC coverage threshold value was calculated as 17 [spades] 0:00:00.393 97M / 2G INFO General (genomic_info_filler.cpp : 69) Trusted kmer low bound: 0 [spades] 0:00:00.394 97M / 2G INFO StageManager (stage.cpp : 166) STAGE == Gap Closer [spades] 0:00:00.394 97M / 2G INFO General (graph_pack.hpp : 105) Index refill [spades] 0:00:00.394 97M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.394 97M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.394 97M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.395 97M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166468 Gb [spades] 0:00:00.395 97M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 58184 [spades] 0:00:00.459 2G / 2G INFO General (edge_index_builders.hpp : 82) Used 588 sequences. [spades] 0:00:00.476 113M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.494 113M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8793 kmers in total. [spades] 0:00:00.495 113M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.501 113M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.521 113M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.523 113M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 13144 bytes occupied (11.9586 bits per kmer). [spades] 0:00:00.523 113M / 2G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. [spades] 0:00:00.527 113M / 2G INFO General (edge_index.hpp : 92) Index refilled [spades] 0:00:00.529 113M / 2G INFO General (gap_closer.cpp : 147) Preparing shift maps [spades] 0:00:00.529 113M / 2G INFO General (gap_closer.cpp : 107) Processing paired reads (takes a while) [spades] 0:00:00.532 113M / 2G INFO General (gap_closer.cpp : 126) Used 23 paired reads [spades] 0:00:00.532 113M / 2G INFO General (gap_closer.cpp : 128) Merging paired indices [spades] 0:00:00.533 113M / 2G INFO GapCloser (gap_closer.cpp : 332) Closing short gaps [spades] 0:00:00.533 113M / 2G INFO GapCloser (gap_closer.cpp : 364) Closing short gaps complete: filled 0 gaps after checking 0 candidates [spades] 0:00:00.537 113M / 2G INFO StageManager (stage.cpp : 166) STAGE == Raw Simplification [spades] 0:00:00.538 113M / 2G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning [spades] 0:00:00.538 113M / 2G INFO General (graph_simplification.hpp : 671) Flanking coverage based disconnection disabled [spades] 0:00:00.538 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover [spades] 0:00:00.543 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times [spades] 0:00:00.543 113M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification [spades] 0:00:00.544 113M / 2G INFO General (simplification.cpp : 383) Graph simplification started [spades] 0:00:00.544 113M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.544 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 1 [spades] 0:00:00.545 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.549 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 132 times [spades] 0:00:00.550 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.555 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 8 times [spades] 0:00:00.555 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.558 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.559 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 2 [spades] 0:00:00.559 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.559 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.560 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.560 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.560 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.561 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.561 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 3 [spades] 0:00:00.561 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.561 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.561 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.562 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.562 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.562 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.562 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 4 [spades] 0:00:00.562 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.563 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.563 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.563 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.563 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.563 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.564 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 5 [spades] 0:00:00.564 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.564 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.564 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.564 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.565 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.565 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.565 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 6 [spades] 0:00:00.565 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.566 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.566 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.566 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.566 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.566 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.567 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 7 [spades] 0:00:00.567 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.567 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.567 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.567 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.568 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.568 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.568 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 8 [spades] 0:00:00.568 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.568 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.569 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.569 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.569 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.569 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.569 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 9 [spades] 0:00:00.570 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.570 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.570 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.570 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.570 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.571 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.571 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 10 [spades] 0:00:00.571 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.571 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.571 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.572 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.572 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.572 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.572 113M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 11 [spades] 0:00:00.573 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.574 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.574 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.576 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.576 113M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.577 113M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.577 113M / 2G INFO StageManager (stage.cpp : 166) STAGE == Gap Closer [spades] 0:00:00.577 113M / 2G INFO General (graph_pack.hpp : 105) Index refill [spades] 0:00:00.578 113M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.578 113M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.579 113M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.579 113M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166448 Gb [spades] 0:00:00.579 113M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 58177 [spades] 0:00:00.641 2G / 2G INFO General (edge_index_builders.hpp : 82) Used 26 sequences. [spades] 0:00:00.649 121M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.665 121M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 2088 kmers in total. [spades] 0:00:00.665 121M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.670 121M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.688 121M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.689 121M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 10200 bytes occupied (39.0805 bits per kmer). [spades] 0:00:00.690 121M / 2G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. [spades] 0:00:00.693 121M / 2G INFO General (edge_index.hpp : 92) Index refilled [spades] 0:00:00.695 121M / 2G INFO General (gap_closer.cpp : 147) Preparing shift maps [spades] 0:00:00.696 121M / 2G INFO General (gap_closer.cpp : 107) Processing paired reads (takes a while) [spades] 0:00:00.698 121M / 2G INFO General (gap_closer.cpp : 126) Used 23 paired reads [spades] 0:00:00.699 121M / 2G INFO General (gap_closer.cpp : 128) Merging paired indices [spades] 0:00:00.699 121M / 2G INFO GapCloser (gap_closer.cpp : 332) Closing short gaps [spades] 0:00:00.699 121M / 2G INFO GapCloser (gap_closer.cpp : 364) Closing short gaps complete: filled 0 gaps after checking 0 candidates [spades] 0:00:00.703 121M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification Cleanup [spades] 0:00:00.704 121M / 2G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification [spades] 0:00:00.704 121M / 2G INFO General (graph_simplification.hpp : 456) Disconnection of relatively low covered edges disabled [spades] 0:00:00.705 121M / 2G INFO General (graph_simplification.hpp : 493) Complex tip clipping disabled [spades] 0:00:00.705 121M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.705 121M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.708 121M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.709 121M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.713 121M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.714 121M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.718 121M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.719 121M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.720 121M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.720 121M / 2G INFO General (simplification.cpp : 343) Disrupting self-conjugate edges [spades] 0:00:00.721 121M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges [spades] 0:00:00.722 121M / 2G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 12 times [spades] 0:00:00.722 121M / 2G INFO General (simplification.cpp : 496) Counting average coverage [spades] 0:00:00.723 121M / 2G INFO General (simplification.cpp : 502) Average coverage = 31.9224 [spades] 0:00:00.723 121M / 2G INFO StageManager (stage.cpp : 166) STAGE == Contig Output [spades] 0:00:00.724 121M / 2G INFO General (read_converter.cpp : 102) Outputting contigs to /home/piemari/shovill_bam/spades/K91/simplified_contigs [spades] 0:00:00.727 121M / 2G INFO General (binary_converter.cpp : 111) 1 reads written [spades] 0:00:00.732 121M / 2G INFO General (pipeline.cpp : 259) SPAdes finished [spades] 0:00:00.733 121M / 2G INFO General (main.cpp : 107) Assembling time: 0 hours 0 minutes 0 seconds [spades] [spades] ===== K91 finished. [spades] [spades] [spades] ===== K111 started. [spades] [spades] [spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/spades-core /home/piemari/shovill_bam/spades/K111/configs/config.info /home/piemari/shovill_bam/spades/K111/configs/isolate_mode.info [spades] [spades] WARNING: Try to use logger before create one. Level=INFO. Message=Additional contigs is /home/piemari/shovill_bam/spades/K91/simplified_contigs [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K111/configs/config.info [spades] 0:00:00.000 4M / 9M INFO General (main.cpp : 75) Loaded config from /home/piemari/shovill_bam/spades/K111/configs/isolate_mode.info [spades] 0:00:00.000 4M / 10M INFO General (memory_limit.cpp : 49) Memory limit set to 4 Gb [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 85) Starting SPAdes, built from N/A, git revision N/A [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 86) Maximum k-mer length: 128 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 87) Assembling dataset (/home/piemari/shovill_bam/spades/dataset.info) with K=111 [spades] 0:00:00.000 4M / 10M INFO General (main.cpp : 88) Maximum # of threads to use (adjusted due to OMP capabilities): 8 [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 194) SPAdes started [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 201) Starting from stage: read_conversion [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 207) Two-step RR enabled: 0 [spades] 0:00:00.000 4M / 10M INFO General (pipeline.cpp : 218) Will need read mapping, kmer mapper will be attached [spades] 0:00:00.000 4M / 10M INFO StageManager (stage.cpp : 166) STAGE == Binary Read Conversion [spades] 0:00:00.001 4M / 12M INFO General (read_converter.cpp : 53) Binary reads detected [spades] 0:00:00.002 4M / 16M INFO StageManager (stage.cpp : 166) STAGE == de Bruijn graph construction [spades] 0:00:00.002 4M / 16M INFO General (construction.cpp : 115) Contigs from previous K will be used: /home/piemari/shovill_bam/spades/K91/simplified_contigs [spades] 0:00:00.007 4M / 16M INFO General (construction.cpp : 150) Max read length 280 [spades] 0:00:00.007 4M / 16M INFO General (construction.cpp : 153) Max read length without merged 150 [spades] 0:00:00.007 4M / 16M INFO General (construction.cpp : 156) Average read length 193.032 [spades] 0:00:00.007 4M / 16M INFO General (stage.cpp : 113) PROCEDURE == k+1-mer counting [spades] 0:00:00.007 4M / 16M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 8 threads. This might take a while. [spades] 0:00:00.007 4M / 16M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.007 4M / 16M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166632 Gb [spades] 0:00:00.007 4M / 16M INFO General (kmer_splitters.hpp : 97) Using cell size of 87363 [spades] 0:00:00.085 83M / 552M INFO General (kmer_splitters.hpp : 293) Used 868 reads [spades] 0:00:00.085 83M / 552M INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.101 83M / 552M INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8451 kmers in total. [spades] 0:00:00.101 83M / 552M INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.105 83M / 552M INFO General (stage.cpp : 113) PROCEDURE == Extension index construction [spades] 0:00:00.105 83M / 552M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.105 83M / 552M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.105 83M / 552M INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.105 83M / 552M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166533 Gb [spades] 0:00:00.105 83M / 552M INFO General (kmer_splitters.hpp : 97) Using cell size of 43655 [spades] 0:00:00.179 2G / 2G INFO General (kmer_splitters.hpp : 364) Processed 8451 kmers [spades] 0:00:00.180 2G / 2G INFO General (kmer_splitters.hpp : 369) Used 8451 kmers. [spades] 0:00:00.203 97M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.220 99M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8478 kmers in total. [spades] 0:00:00.220 99M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.226 99M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.250 96M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.252 96M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 12992 bytes occupied (12.2595 bits per kmer). [spades] 0:00:00.252 96M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers [spades] 0:00:00.257 96M / 2G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. [spades] 0:00:00.258 96M / 2G INFO General (stage.cpp : 113) PROCEDURE == Condensing graph [spades] 0:00:00.258 96M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths [spades] 0:00:00.263 97M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 373) Extracting unbranching paths finished. 272 sequences extracted [spades] 0:00:00.264 97M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 309) Collecting perfect loops [spades] 0:00:00.265 97M / 2G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 342) Collecting perfect loops finished. 0 loops collected [spades] 0:00:00.266 97M / 2G INFO General (stage.cpp : 113) PROCEDURE == Filling coverage indices (PHM) [spades] 0:00:00.266 97M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.267 97M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.280 97M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 8376 bytes occupied (7.929 bits per kmer). [spades] 0:00:00.280 97M / 2G INFO General (construction.cpp : 429) Collecting k-mer coverage information from reads, this takes a while. [spades] 0:00:00.284 97M / 2G INFO General (construction.cpp : 549) Filling coverage and flanking coverage from PHM [spades] 0:00:00.290 97M / 2G INFO StageManager (stage.cpp : 166) STAGE == EC Threshold Finding [spades] 0:00:00.291 97M / 2G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 2 [spades] 0:00:00.291 97M / 2G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 28 [spades] 0:00:00.291 97M / 2G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 28. Coverage mad: 5.9304 [spades] 0:00:00.291 97M / 2G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model [spades] 0:00:00.297 97M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2 [spades] 0:00:00.310 97M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4 [spades] 0:00:00.342 97M / 2G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8 [spades] 0:00:00.373 97M / 2G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 26.1152. Fitted coverage std. dev: 4.16511 [spades] 0:00:00.373 97M / 2G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.999998 [spades] 0:00:00.374 97M / 2G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 18 [spades] 0:00:00.374 97M / 2G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 14 [spades] 0:00:00.374 97M / 2G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 1059 [spades] 0:00:00.374 97M / 2G INFO General (genomic_info_filler.cpp : 53) Mean coverage was calculated as 26.1152 [spades] 0:00:00.374 97M / 2G INFO General (genomic_info_filler.cpp : 68) EC coverage threshold value was calculated as 14 [spades] 0:00:00.374 97M / 2G INFO General (genomic_info_filler.cpp : 69) Trusted kmer low bound: 0 [spades] 0:00:00.375 97M / 2G INFO StageManager (stage.cpp : 166) STAGE == Gap Closer [spades] 0:00:00.375 97M / 2G INFO General (graph_pack.hpp : 105) Index refill [spades] 0:00:00.375 97M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.375 97M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.375 97M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.376 97M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166477 Gb [spades] 0:00:00.376 97M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 43640 [spades] 0:00:00.444 2G / 2G INFO General (edge_index_builders.hpp : 82) Used 544 sequences. [spades] 0:00:00.465 105M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.487 105M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 8451 kmers in total. [spades] 0:00:00.487 105M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.493 105M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.513 106M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.515 106M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 12976 bytes occupied (12.2835 bits per kmer). [spades] 0:00:00.515 106M / 2G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. [spades] 0:00:00.518 106M / 2G INFO General (edge_index.hpp : 92) Index refilled [spades] 0:00:00.524 106M / 2G INFO General (gap_closer.cpp : 147) Preparing shift maps [spades] 0:00:00.525 106M / 2G INFO General (gap_closer.cpp : 107) Processing paired reads (takes a while) [spades] 0:00:00.527 106M / 2G INFO General (gap_closer.cpp : 126) Used 23 paired reads [spades] 0:00:00.527 106M / 2G INFO General (gap_closer.cpp : 128) Merging paired indices [spades] 0:00:00.527 106M / 2G INFO GapCloser (gap_closer.cpp : 332) Closing short gaps [spades] 0:00:00.528 106M / 2G INFO GapCloser (gap_closer.cpp : 364) Closing short gaps complete: filled 0 gaps after checking 0 candidates [spades] 0:00:00.528 106M / 2G INFO StageManager (stage.cpp : 166) STAGE == Raw Simplification [spades] 0:00:00.529 106M / 2G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning [spades] 0:00:00.529 106M / 2G INFO General (simplification.cpp : 63) Most init cleaning disabled on main iteration [spades] 0:00:00.530 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover [spades] 0:00:00.530 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times [spades] 0:00:00.530 106M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification [spades] 0:00:00.531 106M / 2G INFO General (simplification.cpp : 383) Graph simplification started [spades] 0:00:00.531 106M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.531 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 1 [spades] 0:00:00.532 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.533 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 114 times [spades] 0:00:00.534 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.536 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 5 times [spades] 0:00:00.536 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.537 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.537 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 2 [spades] 0:00:00.537 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.538 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.538 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.538 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.539 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.539 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.539 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 3 [spades] 0:00:00.539 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.540 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.540 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.540 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.540 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.540 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.541 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 4 [spades] 0:00:00.541 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.541 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.541 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.541 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.542 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.542 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.542 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 5 [spades] 0:00:00.542 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.542 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.543 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.543 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.543 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.543 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.543 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 6 [spades] 0:00:00.544 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.544 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.544 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.544 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.544 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.545 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.545 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 7 [spades] 0:00:00.545 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.545 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.545 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.546 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.546 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.546 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.546 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 8 [spades] 0:00:00.546 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.547 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.547 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.547 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.547 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.547 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.548 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 9 [spades] 0:00:00.548 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.548 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.548 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.548 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.549 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.549 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.549 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 10 [spades] 0:00:00.549 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.549 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.550 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.550 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.550 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.550 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.550 106M / 2G INFO General (simplification.cpp : 388) PROCEDURE == Simplification cycle, iteration 11 [spades] 0:00:00.551 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.553 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.554 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.558 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.559 106M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover [spades] 0:00:00.564 106M / 2G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times [spades] 0:00:00.568 106M / 2G INFO StageManager (stage.cpp : 166) STAGE == Gap Closer [spades] 0:00:00.569 106M / 2G INFO General (graph_pack.hpp : 105) Index refill [spades] 0:00:00.569 106M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index [spades] 0:00:00.569 106M / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. [spades] 0:00:00.570 106M / 2G INFO General (file_limit.hpp : 32) Open file limit set to 131072 [spades] 0:00:00.570 106M / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 0.166454 Gb [spades] 0:00:00.570 106M / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 43635 [spades] 0:00:00.631 2G / 2G INFO General (edge_index_builders.hpp : 82) Used 64 sequences. [spades] 0:00:00.641 119M / 2G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. [spades] 0:00:00.656 119M / 2G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 3182 kmers in total. [spades] 0:00:00.656 119M / 2G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. [spades] 0:00:00.661 119M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices [spades] 0:00:00.681 119M / 2G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. [spades] 0:00:00.682 119M / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 10600 bytes occupied (26.6499 bits per kmer). [spades] 0:00:00.683 119M / 2G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. [spades] 0:00:00.686 119M / 2G INFO General (edge_index.hpp : 92) Index refilled [spades] 0:00:00.689 119M / 2G INFO General (gap_closer.cpp : 147) Preparing shift maps [spades] 0:00:00.689 119M / 2G INFO General (gap_closer.cpp : 107) Processing paired reads (takes a while) [spades] 0:00:00.691 119M / 2G INFO General (gap_closer.cpp : 126) Used 23 paired reads [spades] 0:00:00.692 119M / 2G INFO General (gap_closer.cpp : 128) Merging paired indices [spades] 0:00:00.692 119M / 2G INFO GapCloser (gap_closer.cpp : 332) Closing short gaps [spades] 0:00:00.693 119M / 2G INFO GapCloser (gap_closer.cpp : 364) Closing short gaps complete: filled 0 gaps after checking 0 candidates [spades] 0:00:00.693 119M / 2G INFO StageManager (stage.cpp : 166) STAGE == Simplification Cleanup [spades] 0:00:00.694 119M / 2G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification [spades] 0:00:00.694 119M / 2G INFO General (graph_simplification.hpp : 456) Disconnection of relatively low covered edges disabled [spades] 0:00:00.694 119M / 2G INFO General (graph_simplification.hpp : 493) Complex tip clipping disabled [spades] 0:00:00.695 119M / 2G INFO General (graph_simplification.hpp : 643) Creating parallel br instance [spades] 0:00:00.695 119M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.695 119M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.696 119M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.696 119M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.697 119M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper [spades] 0:00:00.697 119M / 2G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times [spades] 0:00:00.697 119M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover [spades] 0:00:00.698 119M / 2G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times [spades] 0:00:00.698 119M / 2G INFO General (simplification.cpp : 343) Disrupting self-conjugate edges [spades] 0:00:00.698 119M / 2G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges [spades] 0:00:00.700 119M / 2G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 31 times [spades] 0:00:00.701 119M / 2G INFO General (simplification.cpp : 496) Counting average coverage [spades] 0:00:00.701 119M / 2G INFO General (simplification.cpp : 502) Average coverage = 25.1649 [spades] 0:00:00.701 119M / 2G INFO StageManager (stage.cpp : 166) STAGE == Mismatch Correction [spades] 0:00:00.701 119M / 2G INFO General (graph_pack.hpp : 113) Normalizing k-mer map. Total 1220 kmers to process [spades] 0:00:00.702 119M / 2G INFO General (graph_pack.hpp : 115) Normalizing done [spades] 0:00:00.714 119M / 2G INFO General (mismatch_shall_not_pass.hp: 195) Finished collecting potential mismatches positions [spades] 0:00:00.714 119M / 2G INFO General (mismatch_shall_not_pass.hp: 310) All edges processed [spades] 0:00:00.715 119M / 2G INFO General (mismatch_correction.cpp : 27) Corrected 0 nucleotides [spades] 0:00:00.715 119M / 2G INFO StageManager (stage.cpp : 166) STAGE == Contig Output [spades] 0:00:00.716 119M / 2G INFO General (contig_output.hpp : 21) Outputting contigs to /home/piemari/shovill_bam/spades/K111/before_rr.fasta [spades] 0:00:00.719 119M / 2G INFO General (contig_output_stage.cpp : 146) Writing GFA graph to /home/piemari/shovill_bam/spades/K111/assembly_graph_after_simplification.gfa [spades] 0:00:00.719 119M / 2G INFO StageManager (stage.cpp : 166) STAGE == Paired Information Counting [spades] 0:00:00.719 119M / 2G INFO General (graph_pack.hpp : 113) Normalizing k-mer map. Total 1220 kmers to process [spades] 0:00:00.720 119M / 2G INFO General (graph_pack.hpp : 115) Normalizing done [spades] 0:00:00.720 119M / 2G INFO General (pair_info_count.cpp : 322) Min edge length for estimation: 1140 [spades] 0:00:00.720 119M / 2G INFO General (pair_info_count.cpp : 333) Estimating insert size for library #0 [spades] 0:00:00.720 119M / 2G INFO General (pair_info_count.cpp : 190) Estimating insert size (takes a while) [spades] 0:00:00.763 263M / 2G INFO General (pair_info_count.cpp : 39) Selecting usual mapper [spades] 0:00:00.967 263M / 2G INFO General (sequence_mapper_notifier.h: 94) Total 410 reads processed [spades] 0:00:01.259 263M / 2G INFO General (pair_info_count.cpp : 208) Edge pairs: 2 [spades] 0:00:01.261 263M / 2G INFO General (pair_info_count.cpp : 210) 334 paired reads (81.4634% of all) aligned to long edges [spades] 0:00:01.263 119M / 2G INFO General (pair_info_count.cpp : 352) Insert size = 201.347, deviation = 42.1646, left quantile = 150, right quantile = 261, read length = 150 [spades] 0:00:01.263 119M / 2G INFO General (pair_info_count.cpp : 373) Filtering data for library #0 [spades] 0:00:01.266 119M / 2G INFO General (pair_info_count.cpp : 39) Selecting usual mapper [spades] 0:00:01.268 119M / 2G INFO General (sequence_mapper_notifier.h: 94) Total 410 reads processed [spades] 0:00:01.268 119M / 2G INFO General (pair_info_count.cpp : 385) Mapping library #0 [spades] 0:00:01.269 119M / 2G INFO General (pair_info_count.cpp : 387) Mapping paired reads (takes a while) [spades] 0:00:01.269 119M / 2G INFO General (pair_info_count.cpp : 285) Left insert size quantile 150, right insert size quantile 261, filtering threshold 2, rounding threshold 0 [spades] 0:00:01.277 119M / 2G INFO General (pair_info_count.cpp : 39) Selecting usual mapper [spades] 0:00:01.280 119M / 2G INFO General (sequence_mapper_notifier.h: 94) Total 410 reads processed [spades] 0:00:01.283 119M / 2G INFO StageManager (stage.cpp : 166) STAGE == Distance Estimation [spades] 0:00:01.283 119M / 2G INFO General (distance_estimation.cpp : 174) Processing library #0 [spades] 0:00:01.284 119M / 2G INFO General (distance_estimation.cpp : 150) Weight Filter Done [spades] 0:00:01.284 119M / 2G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SIMPLE distance estimator [spades] 0:00:01.286 119M / 2G INFO General (distance_estimation.cpp : 35) Filtering info [spades] 0:00:01.287 119M / 2G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 2 [spades] 0:00:01.287 119M / 2G INFO General (pair_info_filters.hpp : 263) Done filtering [spades] 0:00:01.287 119M / 2G INFO General (distance_estimation.cpp : 157) Refining clustered pair information [spades] 0:00:01.287 119M / 2G INFO General (distance_estimation.cpp : 159) The refining of clustered pair information has been finished [spades] 0:00:01.288 119M / 2G INFO General (distance_estimation.cpp : 161) Improving paired information [spades] 0:00:01.288 119M / 2G INFO PairInfoImprover (pair_info_improver.hpp : 102) Paired info stats: missing = 0; contradictional = 0 [spades] 0:00:01.289 119M / 2G INFO PairInfoImprover (pair_info_improver.hpp : 102) Paired info stats: missing = 0; contradictional = 0 [spades] 0:00:01.289 119M / 2G INFO General (distance_estimation.cpp : 104) Filling scaffolding index [spades] 0:00:01.290 119M / 2G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SMOOTHING distance estimator [spades] 0:00:01.290 119M / 2G INFO General (distance_estimation.cpp : 35) Filtering info [spades] 0:00:01.290 119M / 2G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 2 [spades] 0:00:01.291 119M / 2G INFO General (pair_info_filters.hpp : 263) Done filtering [spades] 0:00:01.291 119M / 2G INFO General (distance_estimation.cpp : 183) Clearing raw paired index [spades] 0:00:01.291 119M / 2G INFO StageManager (stage.cpp : 166) STAGE == Repeat Resolving [spades] 0:00:01.291 119M / 2G INFO General (repeat_resolving.cpp : 69) Using Path-Extend repeat resolving [spades] 0:00:01.292 119M / 2G INFO General (launcher.cpp : 538) ExSPAnder repeat resolving tool started [spades] 0:00:01.293 119M / 2G INFO General (launcher.cpp : 404) Creating main extenders, unique edge length = 2000 [spades] 0:00:01.293 119M / 2G INFO General (extenders_logic.cpp : 311) Estimated coverage of library #0 is 25.1649 [spades] 0:00:01.293 119M / 2G INFO General (extenders_logic.cpp : 311) Estimated coverage of library #0 is 25.1649 [spades] 0:00:01.294 119M / 2G INFO General (extenders_logic.cpp : 519) Using 1 paired-end library [spades] 0:00:01.294 119M / 2G INFO General (extenders_logic.cpp : 520) Using 1 paired-end scaffolding library [spades] 0:00:01.294 119M / 2G INFO General (extenders_logic.cpp : 521) Using 0 single read libraries [spades] 0:00:01.294 119M / 2G INFO General (launcher.cpp : 432) Total number of extenders is 3 [spades] 0:00:01.294 119M / 2G INFO General (launcher.cpp : 244) Finalizing paths [spades] 0:00:01.295 119M / 2G INFO General (launcher.cpp : 246) Deduplicating paths [spades] 0:00:01.295 119M / 2G INFO General (launcher.cpp : 250) Paths deduplicated [spades] 0:00:01.295 119M / 2G INFO PEResolver (pe_resolver.hpp : 295) Removing overlaps [spades] 0:00:01.295 119M / 2G INFO PEResolver (pe_resolver.hpp : 298) Sorting paths [spades] 0:00:01.295 119M / 2G INFO PEResolver (pe_resolver.hpp : 305) Marking overlaps [spades] 0:00:01.295 119M / 2G INFO OverlapRemover (pe_resolver.hpp : 130) Marking start/end overlaps [spades] 0:00:01.296 119M / 2G INFO OverlapRemover (pe_resolver.hpp : 133) Marking remaining overlaps [spades] 0:00:01.296 119M / 2G INFO PEResolver (pe_resolver.hpp : 308) Splitting paths [spades] 0:00:01.296 119M / 2G INFO PEResolver (pe_resolver.hpp : 313) Deduplicating paths [spades] 0:00:01.296 119M / 2G INFO PEResolver (pe_resolver.hpp : 315) Overlaps removed [spades] 0:00:01.296 119M / 2G INFO General (launcher.cpp : 267) Paths finalized [spades] 0:00:01.296 119M / 2G INFO General (launcher.cpp : 439) Closing gaps in paths [spades] 0:00:01.297 119M / 2G INFO General (launcher.cpp : 467) Gap closing completed [spades] 0:00:01.297 119M / 2G INFO General (launcher.cpp : 296) Traversing tandem repeats [spades] 0:00:01.297 119M / 2G INFO General (launcher.cpp : 306) Traversed 0 loops [spades] 0:00:01.297 119M / 2G INFO General (launcher.cpp : 244) Finalizing paths [spades] 0:00:01.297 119M / 2G INFO General (launcher.cpp : 246) Deduplicating paths [spades] 0:00:01.298 119M / 2G INFO General (launcher.cpp : 250) Paths deduplicated [spades] 0:00:01.298 119M / 2G INFO PEResolver (pe_resolver.hpp : 295) Removing overlaps [spades] 0:00:01.298 119M / 2G INFO PEResolver (pe_resolver.hpp : 298) Sorting paths [spades] 0:00:01.298 119M / 2G INFO PEResolver (pe_resolver.hpp : 305) Marking overlaps [spades] 0:00:01.298 119M / 2G INFO OverlapRemover (pe_resolver.hpp : 130) Marking start/end overlaps [spades] 0:00:01.298 119M / 2G INFO OverlapRemover (pe_resolver.hpp : 133) Marking remaining overlaps [spades] 0:00:01.299 119M / 2G INFO PEResolver (pe_resolver.hpp : 308) Splitting paths [spades] 0:00:01.299 119M / 2G INFO PEResolver (pe_resolver.hpp : 313) Deduplicating paths [spades] 0:00:01.299 119M / 2G INFO PEResolver (pe_resolver.hpp : 315) Overlaps removed [spades] 0:00:01.299 119M / 2G INFO General (launcher.cpp : 267) Paths finalized [spades] 0:00:01.299 119M / 2G INFO General (launcher.cpp : 596) ExSPAnder repeat resolving tool finished [spades] 0:00:01.299 119M / 2G INFO StageManager (stage.cpp : 166) STAGE == Contig Output [spades] 0:00:01.300 119M / 2G INFO General (contig_output.hpp : 21) Outputting contigs to /home/piemari/shovill_bam/spades/K111/before_rr.fasta [spades] 0:00:01.302 119M / 2G INFO General (contig_output_stage.cpp : 146) Writing GFA graph to /home/piemari/shovill_bam/spades/K111/assembly_graph_with_scaffolds.gfa [spades] 0:00:01.302 119M / 2G INFO General (contig_output_stage.cpp : 160) Outputting FastG graph to /home/piemari/shovill_bam/spades/K111/assembly_graph.fastg [spades] 0:00:01.304 119M / 2G INFO General (contig_output_stage.cpp : 190) Breaking scaffolds [spades] 0:00:01.304 119M / 2G INFO General (contig_output_stage.cpp : 95) Outputting contigs to /home/piemari/shovill_bam/spades/K111/final_contigs.fasta [spades] 0:00:01.306 119M / 2G INFO General (contig_output_stage.cpp : 101) Outputting FastG paths to /home/piemari/shovill_bam/spades/K111/final_contigs.paths [spades] 0:00:01.307 119M / 2G INFO General (contig_output_stage.cpp : 95) Outputting contigs to /home/piemari/shovill_bam/spades/K111/scaffolds.fasta [spades] 0:00:01.308 119M / 2G INFO General (contig_output_stage.cpp : 101) Outputting FastG paths to /home/piemari/shovill_bam/spades/K111/scaffolds.paths [spades] 0:00:01.310 119M / 2G INFO General (contig_output_stage.cpp : 108) Populating GFA with scaffold paths [spades] 0:00:01.312 119M / 2G INFO General (pipeline.cpp : 259) SPAdes finished [spades] 0:00:01.313 116M / 2G INFO General (main.cpp : 107) Assembling time: 0 hours 0 minutes 1 seconds [spades] [spades] ===== K111 finished. [spades] [spades] [spades] ===== Copy files started. [spades] [spades] [spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/python /home/piemari/apps/conda/envs/metaphlan/share/spades/spades_pipeline/scripts/copy_files.py /home/piemari/shovill_bam/spades/K111/before_rr.fasta /home/piemari/shovill_bam/spades/before_rr.fasta /home/piemari/shovill_bam/spades/K111/assembly_graph_after_simplification.gfa /home/piemari/shovill_bam/spades/assembly_graph_after_simplification.gfa /home/piemari/shovill_bam/spades/K111/final_contigs.fasta /home/piemari/shovill_bam/spades/contigs.fasta /home/piemari/shovill_bam/spades/K111/first_pe_contigs.fasta /home/piemari/shovill_bam/spades/first_pe_contigs.fasta /home/piemari/shovill_bam/spades/K111/strain_graph.gfa /home/piemari/shovill_bam/spades/strain_graph.gfa /home/piemari/shovill_bam/spades/K111/scaffolds.fasta /home/piemari/shovill_bam/spades/scaffolds.fasta /home/piemari/shovill_bam/spades/K111/scaffolds.paths /home/piemari/shovill_bam/spades/scaffolds.paths /home/piemari/shovill_bam/spades/K111/assembly_graph_with_scaffolds.gfa /home/piemari/shovill_bam/spades/assembly_graph_with_scaffolds.gfa /home/piemari/shovill_bam/spades/K111/assembly_graph.fastg /home/piemari/shovill_bam/spades/assembly_graph.fastg /home/piemari/shovill_bam/spades/K111/final_contigs.paths /home/piemari/shovill_bam/spades/contigs.paths [spades] [spades] [spades] ===== Copy files finished. [spades] [spades] [spades] ===== Assembling finished. [spades] [spades] [spades] ===== Breaking scaffolds started. [spades] [spades] [spades] == Running: /home/piemari/apps/conda/envs/metaphlan/bin/python /home/piemari/apps/conda/envs/metaphlan/share/spades/spades_pipeline/scripts/breaking_scaffolds_script.py --result_scaffolds_filename /home/piemari/shovill_bam/spades/scaffolds.fasta --misc_dir /home/piemari/shovill_bam/spades/misc --threshold_for_breaking_scaffolds 3 [spades] [spades] [spades] ===== Breaking scaffolds finished. [spades] [spades] [spades] ===== Terminate started. [spades] [spades] [spades] ===== Terminate finished. [spades] [spades] * Assembled contigs are in /home/piemari/shovill_bam/spades/contigs.fasta [spades] * Assembled scaffolds are in /home/piemari/shovill_bam/spades/scaffolds.fasta [spades] * Paths in the assembly graph corresponding to the contigs are in /home/piemari/shovill_bam/spades/contigs.paths [spades] * Paths in the assembly graph corresponding to the scaffolds are in /home/piemari/shovill_bam/spades/scaffolds.paths [spades] * Assembly graph is in /home/piemari/shovill_bam/spades/assembly_graph.fastg [spades] * Assembly graph in GFA format is in /home/piemari/shovill_bam/spades/assembly_graph_with_scaffolds.gfa [spades] [spades] ======= SPAdes pipeline finished. [spades] [spades] SPAdes log can be found here: /home/piemari/shovill_bam/spades/spades.log [spades] [spades] Thank you for using SPAdes! [shovill] Checking for assembly errors in spades.fasta [shovill] Running: bwa index spades.fasta 2>&1 | sed 's/^/[bwa-index] /' | tee -a shovill.log [bwa-index] [bwa_index] Pack FASTA... 0.00 sec [bwa-index] [bwa_index] Construct BWT for the packed sequence... [bwa-index] [bwa_index] 0.00 seconds elapse. [bwa-index] [bwa_index] Update BWT... 0.00 sec [bwa-index] [bwa_index] Pack forward-only FASTA... 0.00 sec [bwa-index] [bwa_index] Construct SA from BWT and Occ... 0.00 sec [bwa-index] [main] Version: 0.7.17-r1188 [bwa-index] [main] CMD: bwa index spades.fasta [bwa-index] [main] Real time: 0.012 sec; CPU: 0.004 sec [shovill] Running: samtools faidx spades.fasta 2>&1 | sed 's/^/[faidx] /' | tee -a shovill.log [shovill] Running: (bwa mem -v 3 -x intractg -t 8 spades.fasta R1.fq.gz R2.fq.gz | samclip --ref spades.fasta.fai | samtools sort --threads 2 -m 1024m --reference spades.fasta -T /tmp -o shovill.bam) 2>&1 | sed 's/^/[bwa+samtools-sort] /' | tee -a shovill.log [bwa+samtools-sort] [M::bwa_idx_load_from_disk] read 0 ALT contigs [bwa+samtools-sort] [M::process] read 820 sequences (123000 bp)... [bwa+samtools-sort] [M::mem_pestat] # candidate unique pairs for (FF, FR, RF, RR): (0, 410, 0, 0) [bwa+samtools-sort] [M::mem_pestat] skip orientation FF as there are not enough pairs [bwa+samtools-sort] [M::mem_pestat] analyzing insert size distribution for orientation FR... [bwa+samtools-sort] [M::mem_pestat] (25, 50, 75) percentile: (163, 197, 230) [bwa+samtools-sort] [M::mem_pestat] low and high boundaries for computing mean and std.dev: (29, 364) [bwa+samtools-sort] [M::mem_pestat] mean and std.dev: (200.81, 42.23) [bwa+samtools-sort] [M::mem_pestat] low and high boundaries for proper pairs: (1, 431) [bwa+samtools-sort] [M::mem_pestat] skip orientation RF as there are not enough pairs [bwa+samtools-sort] [M::mem_pestat] skip orientation RR as there are not enough pairs [bwa+samtools-sort] [M::mem_process_seqs] Processed 820 reads in 0.101 CPU sec, 0.021 real sec [bwa+samtools-sort] [samclip] samclip 0.4.0 by Torsten Seemann (@torstenseemann) [bwa+samtools-sort] [samclip] Loading: spades.fasta.fai [bwa+samtools-sort] [samclip] Found 1 sequences in spades.fasta.fai [bwa+samtools-sort] [main] Version: 0.7.17-r1188 [bwa+samtools-sort] [main] CMD: bwa mem -v 3 -x intractg -t 8 spades.fasta R1.fq.gz R2.fq.gz [bwa+samtools-sort] [main] Real time: 0.053 sec; CPU: 0.107 sec [bwa+samtools-sort] [samclip] Total SAM records 820, removed 63, allowed 123, passed 757 [bwa+samtools-sort] [samclip] Header contained 2 lines [bwa+samtools-sort] [samclip] Done. [bwa+samtools-sort] [bam_sort_core] merging from 0 files and 2 in-memory blocks... [shovill] Running: samtools index shovill.bam 2>&1 | sed 's/^/[samtools-index] /' | tee -a shovill.log [shovill] Correcting errors in spades.fasta [shovill] Running: pilon --genome spades.fasta --frags shovill.bam --minmq 60 --minqual 3 --fix bases --output pilon --threads 8 --changes --mindepth 0.25 2>&1 | sed 's/^/[pilon] /' | tee -a shovill.log [pilon] Picked up _JAVA_OPTIONS: -Xmx4g [pilon] Pilon version 1.24 Thu Jan 28 13:00:45 2021 -0500 [pilon] --threads argument no longer supported; ignoring! [pilon] Genome: spades.fasta [pilon] Fixing snps, indels [pilon] Input genome size: 1251 [pilon] Processing NODE_1_length_1251_cov_25.164912:1-1251 [pilon] frags shovill.bam: coverage 79 [pilon] Total Reads: 757, Coverage: 79, minDepth: 20 [pilon] Confirmed 1152 of 1251 bases (92,09%) [pilon] Corrected 0 snps; 0 ambiguous bases; corrected 0 small insertions totaling 0 bases, 0 small deletions totaling 0 bases [pilon] NODE_1_length_1251_cov_25.164912:1-1251 log: [pilon] Finished processing NODE_1_length_1251_cov_25.164912:1-1251 [pilon] Writing NODE_1_length_1251_cov_25.164912:1-1251 changes to pilon.changes [pilon] Writing updated NODE_1_length_1251_cov_25.164912_pilon to pilon.fasta [pilon] Mean frags coverage: 79 [pilon] Mean total coverage: 79 [shovill] Repaired 0 contigs from spades.fasta at 0 positions. [shovill] Assembly is 1251, estimated genome size was 1188 (+5.30%) [shovill] Using genome graph file 'spades/assembly_graph_with_scaffolds.gfa' => 'contigs.gfa' [shovill] Walltime used: 0 min 10 sec [shovill] Results in: /home/piemari/shovill_bam [shovill] Final assembly graph: /home/piemari/shovill_bam/contigs.gfa [shovill] Final assembly contigs: /home/piemari/shovill_bam/contigs.fa [shovill] It contains 1 (min=75) contigs totalling 1251 bp. [shovill] Have a suggestion for shovill? Tell me at https://github.com/tseemann/shovill/issues [shovill] Done.