Mercurial > repos > iuc > shovill
diff test-data/shovill_std_log @ 8:ad80238462c1 draft
planemo upload for repository https://github.com/galaxyproject/tools-iuc/tree/master/tools/shovill commit 1e28eb4ffcf3d9168877c291d27e533b96021445
| author | iuc |
|---|---|
| date | Fri, 16 Sep 2022 14:39:43 +0000 |
| parents | |
| children |
line wrap: on
line diff
--- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/test-data/shovill_std_log Fri Sep 16 14:39:43 2022 +0000 @@ -0,0 +1,1460 @@ +[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.