annotate test-data/shovill_std_log @ 8:ad80238462c1 draft

planemo upload for repository https://github.com/galaxyproject/tools-iuc/tree/master/tools/shovill commit 1e28eb4ffcf3d9168877c291d27e533b96021445

[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.