Spades stoped with unknown errors! #342

sunnycqcn · 2019-07-30T16:16:36Z

Hello,
I am assembling a fungal genome (about 50Mb) using Spades. I tried lots times. I met the same errors. Could you help me check what it happen? I have attached my log file and parameters file.
Thanks,
Fuyou

sunnycqcn · 2019-07-30T16:17:47Z

No attachments? I loaded again.

asl · 2019-07-30T16:18:58Z

Please do attach the logs

sunnycqcn · 2019-07-30T18:41:03Z

parameters:
Command line: /home/AAFC-AAC/fuf/SPAdes/bin/spades.py -t 20 --memory 1024 -k 21,33,47,55,59,65,67,73,77 --pe1-1 /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R1.fastq.gz --pe1-2 /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R2.fastq.gz --pacbio /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06.fastq --trusted-contigs /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06.sm.fasta -o /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta

System information:
SPAdes version: 3.13.0
Python version: 3.7.3
OS: Linux-3.10.0-862.11.6.el7.x86_64-x86_64-with-centos-7.5.1804-Core

Output dir: /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta
Mode: read error correction and assembling
Debug mode is turned OFF

Dataset parameters:
Multi-cell mode (you should set '--sc' flag if input data was obtained with MDA (single-cell) technology or --meta flag if processing metagenomic dataset)
Reads:
Library number: 1, library type: paired-end
orientation: fr
left reads: ['/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R1.fastq.gz']
right reads: ['/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R2.fastq.gz']
interlaced reads: not specified
single reads: not specified
merged reads: not specified
Library number: 2, library type: pacbio
left reads: not specified
right reads: not specified
interlaced reads: not specified
single reads: ['/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06.fastq']
merged reads: not specified
Library number: 3, library type: trusted-contigs
left reads: not specified
right reads: not specified
interlaced reads: not specified
single reads: ['/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06.sm.fasta']
merged reads: not specified
Read error correction parameters:
Iterations: 1
PHRED offset will be auto-detected
Corrected reads will be compressed
Assembly parameters:
k: [21, 33, 47, 55, 59, 65, 67, 73, 77]
Repeat resolution is enabled
Mismatch careful mode is turned OFF
MismatchCorrector will be SKIPPED
Coverage cutoff is turned OFF
Other parameters:
Dir for temp files: /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/tmp
Threads: 20
Memory limit (in Gb): 1024

sunnycqcn · 2019-07-30T18:51:37Z

log file:
Command line: /home/AAFC-AAC/fuf/SPAdes/bin/spades.py -t 20 --memory 1024 -k 21,33,47,55,59,65,67,73,77 --pe1-1 /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R1.fastq.gz --pe1-2 /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R2.fastq.gz --pacbio /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06.fastq --trusted-contigs /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06.sm.fasta -o /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta

System information:
SPAdes version: 3.13.0
Python version: 3.7.3
OS: Linux-3.10.0-862.11.6.el7.x86_64-x86_64-with-centos-7.5.1804-Core

Output dir: /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta
Mode: read error correction and assembling
Debug mode is turned OFF

Dataset parameters:
Multi-cell mode (you should set '--sc' flag if input data was obtained with MDA (single-cell) technology or --meta flag if processing metagenomic dataset)
Reads:
Library number: 1, library type: paired-end
orientation: fr
left reads: ['/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R1.fastq.gz']
right reads: ['/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R2.fastq.gz']
interlaced reads: not specified
single reads: not specified
merged reads: not specified
Library number: 2, library type: pacbio
left reads: not specified
right reads: not specified
interlaced reads: not specified
single reads: ['/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06.fastq']
merged reads: not specified
Library number: 3, library type: trusted-contigs
left reads: not specified
right reads: not specified
interlaced reads: not specified
single reads: ['/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06.sm.fasta']
merged reads: not specified
Read error correction parameters:
Iterations: 1
PHRED offset will be auto-detected
Corrected reads will be compressed
Assembly parameters:
k: [21, 33, 47, 55, 59, 65, 67, 73, 77]
Repeat resolution is enabled
Mismatch careful mode is turned OFF
MismatchCorrector will be SKIPPED
Coverage cutoff is turned OFF
Other parameters:
Dir for temp files: /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/tmp
Threads: 20
Memory limit (in Gb): 1024

======= SPAdes pipeline started. Log can be found here: /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/spades.log

===== Read error correction started.

== Running read error correction tool: /home/AAFC-AAC/fuf/SPAdes/bin/spades-hammer /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/corrected/configs/config.info

0:00:00.000 4M / 4M INFO General (main.cpp : 75) Starting BayesHammer, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.001 4M / 4M INFO General (main.cpp : 76) Loading config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/corrected/configs/config.info
0:00:00.002 4M / 4M INFO General (main.cpp : 78) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.002 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.002 4M / 4M INFO General (main.cpp : 86) Trying to determine PHRED offset
0:00:00.003 4M / 4M INFO General (main.cpp : 92) Determined value is 33
0:00:00.003 4M / 4M INFO General (hammer_tools.cpp : 36) Hamming graph threshold tau=1, k=21, subkmer positions = [ 0 10 ]
0:00:00.003 4M / 4M INFO General (main.cpp : 113) Size of aux. kmer data 24 bytes
=== ITERATION 0 begins ===
0:00:00.008 4M / 4M INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:00.008 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:00:00.010 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.010 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0666 Gb
0:00:00.011 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 209715
0:00:02.105 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 97) Processing /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R1.fastq.gz
0:00:35.159 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 107) Processed 7150990 reads
0:00:35.159 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 97) Processing /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R2.fastq.gz
0:01:09.486 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 107) Processed 14301980 reads
0:01:09.486 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 112) Total 14301980 reads processed
0:01:10.668 80M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:13.695 80M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 197117738 kmers in total.
0:01:13.695 80M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:21.221 80M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:26.953 144M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:33.559 144M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 91411992 bytes occupied (3.70994 bits per kmer).
0:01:33.567 144M / 11G INFO K-mer Counting (kmer_data.cpp : 356) Arranging kmers in hash map order
0:01:41.141 3G / 11G INFO General (main.cpp : 148) Clustering Hamming graph.
0:04:14.047 3G / 11G INFO General (main.cpp : 155) Extracting clusters
0:05:20.702 3G / 11G INFO General (main.cpp : 167) Clustering done. Total clusters: 109923440
0:05:20.709 1G / 11G INFO K-mer Counting (kmer_data.cpp : 376) Collecting K-mer information, this takes a while.
0:05:22.952 6G / 11G INFO K-mer Counting (kmer_data.cpp : 382) Processing /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R1.fastq.gz
0:06:13.283 6G / 11G INFO K-mer Counting (kmer_data.cpp : 382) Processing /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R2.fastq.gz
0:07:04.110 6G / 11G INFO K-mer Counting (kmer_data.cpp : 389) Collection done, postprocessing.
0:07:05.276 6G / 11G INFO K-mer Counting (kmer_data.cpp : 403) There are 197117738 kmers in total. Among them 130796934 (66.3547%) are singletons.
0:07:05.276 6G / 11G INFO General (main.cpp : 173) Subclustering Hamming graph
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 649) Subclustering done. Total 1450 non-read kmers were generated.
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 650) Subclustering statistics:
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 651) Total singleton hamming clusters: 72253654. Among them 20698336 (28.6468%) are good
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 652) Total singleton subclusters: 757444. Among them 754915 (99.6661%) are good
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 653) Total non-singleton subcluster centers: 39809919. Among them 21280818 (53.4561%) are good
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 654) Average size of non-trivial subcluster: 3.1366 kmers
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 655) Average number of sub-clusters per non-singleton cluster: 1.07692
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 656) Total solid k-mers: 42734069
0:08:56.187 6G / 11G INFO Hamming Subclustering (kmer_cluster.cpp : 657) Substitution probabilities: 4,4
0:08:56.385 6G / 11G INFO General (main.cpp : 178) Finished clustering.
0:08:56.385 6G / 11G INFO General (main.cpp : 197) Starting solid k-mers expansion in 20 threads.
0:09:45.991 6G / 11G INFO General (main.cpp : 218) Solid k-mers iteration 0 produced 1828650 new k-mers.
0:10:35.615 6G / 11G INFO General (main.cpp : 218) Solid k-mers iteration 1 produced 78786 new k-mers.
0:11:25.252 6G / 11G INFO General (main.cpp : 218) Solid k-mers iteration 2 produced 7942 new k-mers.
0:12:15.013 6G / 11G INFO General (main.cpp : 218) Solid k-mers iteration 3 produced 804 new k-mers.
0:13:04.755 6G / 11G INFO General (main.cpp : 218) Solid k-mers iteration 4 produced 47 new k-mers.
0:13:54.592 6G / 11G INFO General (main.cpp : 218) Solid k-mers iteration 5 produced 28 new k-mers.
0:14:44.214 6G / 11G INFO General (main.cpp : 218) Solid k-mers iteration 6 produced 0 new k-mers.
0:14:44.214 6G / 11G INFO General (main.cpp : 222) Solid k-mers finalized
0:14:44.214 6G / 11G INFO General (hammer_tools.cpp : 220) Starting read correction in 20 threads.
0:14:44.214 6G / 11G INFO General (hammer_tools.cpp : 233) Correcting pair of reads: /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R1.fastq.gz and /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/BL06_R2.fastq.gz
0:14:56.249 7G / 11G INFO General (hammer_tools.cpp : 168) Prepared batch 0 of 2000000 reads.
0:15:08.964 7G / 11G INFO General (hammer_tools.cpp : 175) Processed batch 0
0:15:12.292 7G / 11G INFO General (hammer_tools.cpp : 185) Written batch 0
0:15:23.537 7G / 11G INFO General (hammer_tools.cpp : 168) Prepared batch 1 of 2000000 reads.
0:15:35.678 7G / 11G INFO General (hammer_tools.cpp : 175) Processed batch 1
0:15:38.847 7G / 11G INFO General (hammer_tools.cpp : 185) Written batch 1
0:15:50.130 7G / 11G INFO General (hammer_tools.cpp : 168) Prepared batch 2 of 2000000 reads.
0:16:04.250 7G / 11G INFO General (hammer_tools.cpp : 175) Processed batch 2
0:16:09.158 7G / 11G INFO General (hammer_tools.cpp : 185) Written batch 2
0:16:15.864 7G / 11G INFO General (hammer_tools.cpp : 168) Prepared batch 3 of 1150990 reads.
0:16:24.156 7G / 11G INFO General (hammer_tools.cpp : 175) Processed batch 3
0:16:26.089 7G / 11G INFO General (hammer_tools.cpp : 185) Written batch 3
0:16:32.355 6G / 11G INFO General (hammer_tools.cpp : 274) Correction done. Changed 4763560 bases in 2082727 reads.
0:16:32.355 6G / 11G INFO General (hammer_tools.cpp : 275) Failed to correct 81070 bases out of 1430106393.
0:16:32.402 80M / 11G INFO General (main.cpp : 255) Saving corrected dataset description to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/corrected/corrected.yaml
0:16:32.409 80M / 11G INFO General (main.cpp : 262) All done. Exiting.

== Compressing corrected reads (with gzip)

== Dataset description file was created: /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/corrected/corrected.yaml

===== Read error correction finished.

===== Assembling started.

== Running assembler: K21

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K21/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.001 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.001 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=21
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.001 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.077 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.082 8M / 12M INFO General (read_converter.hpp : 77) Converting reads to binary format for library #0 (takes a while)
0:00:00.082 8M / 12M INFO General (read_converter.hpp : 78) Converting paired reads
0:00:00.364 84M / 84M INFO General (binary_converter.hpp : 93) 16384 reads processed
0:00:00.556 96M / 96M INFO General (binary_converter.hpp : 93) 32768 reads processed
0:00:00.908 116M / 116M INFO General (binary_converter.hpp : 93) 65536 reads processed
0:00:01.543 164M / 164M INFO General (binary_converter.hpp : 93) 131072 reads processed
0:00:02.819 252M / 252M INFO General (binary_converter.hpp : 93) 262144 reads processed
0:00:05.355 432M / 432M INFO General (binary_converter.hpp : 93) 524288 reads processed
0:00:13.112 708M / 708M INFO General (binary_converter.hpp : 93) 1048576 reads processed
0:00:25.951 708M / 708M INFO General (binary_converter.hpp : 93) 2097152 reads processed
0:00:51.757 708M / 708M INFO General (binary_converter.hpp : 93) 4194304 reads processed
0:01:29.479 412M / 708M INFO General (binary_converter.hpp : 117) 7016856 reads written
0:01:30.242 8M / 708M INFO General (read_converter.hpp : 87) Converting single reads
0:01:30.509 176M / 708M INFO General (binary_converter.hpp : 93) 16384 reads processed
0:01:30.610 180M / 708M INFO General (binary_converter.hpp : 93) 32768 reads processed
0:01:30.814 192M / 708M INFO General (binary_converter.hpp : 93) 65536 reads processed
0:01:31.214 212M / 708M INFO General (binary_converter.hpp : 93) 131072 reads processed
0:01:31.438 216M / 708M INFO General (binary_converter.hpp : 117) 133940 reads written
0:01:31.528 8M / 708M INFO General (read_converter.hpp : 95) Converting merged reads
0:01:31.692 168M / 708M INFO General (binary_converter.hpp : 117) 0 reads written
0:01:31.854 8M / 708M INFO General (construction.cpp : 111) Max read length 100
0:01:31.854 8M / 708M INFO General (construction.cpp : 117) Average read length 99.9908
0:01:31.854 8M / 708M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:01:31.856 8M / 708M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:01:31.859 8M / 708M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:01:31.859 8M / 708M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:01:31.859 8M / 708M INFO General (kmer_splitters.hpp : 97) Using cell size of 167772
0:01:46.404 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:01:46.404 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:01:57.020 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:01:57.020 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:59.642 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 38699672 kmers in total.
0:01:59.642 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:02:01.961 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:02:01.963 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:02:01.963 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:02:01.966 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:02:01.966 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:02:01.966 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 209715
0:02:09.605 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 38699672 kmers
0:02:09.605 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 38699672 kmers.
0:02:10.434 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:02:12.654 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 38387529 kmers in total.
0:02:12.654 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:02:15.254 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:16.310 92M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:02:17.637 92M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 17817316 bytes occupied (3.71315 bits per kmer).
0:02:17.672 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:02:19.060 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:02:19.063 132M / 11G INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping
0:02:19.063 132M / 11G INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K)
0:02:19.063 132M / 11G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping
0:02:21.611 128M / 11G INFO Early tip clipping (early_simplification.hpp : 184) 4524969 22-mers were removed by early tip clipper
0:02:21.611 128M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:02:21.664 128M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:02:23.312 160M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 837710 sequences extracted
0:02:24.131 156M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:02:24.588 160M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 4 loops collected
0:02:24.975 372M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:02:24.975 372M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:02:24.975 372M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:25.630 376M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 17955368 bytes occupied (3.71174 bits per kmer).
0:02:25.711 524M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:02:43.020 524M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:02:44.147 524M / 11G INFO General (construction.cpp : 464) Processed 1674752 edges
0:02:44.324 268M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:02:44.332 268M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 5
0:02:44.332 268M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 25
0:02:44.333 268M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 26. Coverage mad: 7.413
0:02:44.333 268M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:02:44.371 268M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:02:44.473 268M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:02:44.820 268M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:02:45.465 268M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:02:45.795 268M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 26.2545. Fitted coverage std. dev: 6.12682
0:02:45.796 268M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.894164
0:02:45.796 268M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 15
0:02:45.796 268M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 15
0:02:45.796 268M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 29186145
0:02:45.797 268M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 26.2545
0:02:45.797 268M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 15
0:02:45.797 268M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:02:45.797 268M / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:02:45.797 268M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:02:45.797 268M / 11G INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled
0:02:45.797 268M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:02:45.847 268M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 6 times
0:02:45.847 268M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:02:45.961 268M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 3679 times
0:02:45.961 268M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:02:50.758 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 160563 times
0:02:50.758 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:02:50.831 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 6279 times
0:02:50.882 280M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:02:50.882 280M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:02:50.882 280M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:02:50.882 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:02:50.882 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:50.951 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2067 times
0:02:50.951 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.461 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 33447 times
0:02:59.461 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.649 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 3105 times
0:02:59.649 284M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:02:59.649 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.732 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 109 times
0:02:59.732 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.099 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 395 times
0:03:00.099 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.334 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 8609 times
0:03:00.335 284M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:03:00.335 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.344 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 26 times
0:03:00.344 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:01.086 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1627 times
0:03:01.086 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:01.225 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 5150 times
0:03:01.225 284M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:03:01.225 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:01.238 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 9 times
0:03:01.238 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:01.702 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1160 times
0:03:01.702 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:01.780 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2985 times
0:03:01.781 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:03:01.781 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:01.789 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 4 times
0:03:01.789 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:02.055 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 695 times
0:03:02.055 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:02.095 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1458 times
0:03:02.095 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:03:02.095 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:02.100 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:02.100 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:02.217 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 353 times
0:03:02.217 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:02.249 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1209 times
0:03:02.249 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:03:02.249 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:02.252 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:02.252 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:02.343 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 254 times
0:03:02.343 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:02.370 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 941 times
0:03:02.370 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:03:02.370 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:02.372 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:02.372 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:02.432 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 206 times
0:03:02.432 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:02.465 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1188 times
0:03:02.465 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:03:02.465 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:02.467 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:02.467 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:02.551 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 270 times
0:03:02.551 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:02.589 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1347 times
0:03:02.589 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:03:02.589 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:02.591 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:02.591 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:02.676 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 286 times
0:03:02.677 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:02.734 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2041 times
0:03:02.734 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:03:02.734 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:02.759 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:02.759 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:03.280 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 492 times
0:03:03.280 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:03.314 280M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:03.314 280M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:03:03.314 280M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:03.318 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:03.318 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:03.318 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:03.318 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:03.318 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:03.318 276M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:03:03.318 276M / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:03:03.318 276M / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:03:03.318 276M / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:03:03.318 276M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:03:03.318 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:03.341 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:03.341 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:03.778 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 2 times
0:03:03.778 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:03.802 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:03.802 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:04.236 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:04.236 276M / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:03:04.623 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:03:04.649 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 254 times
0:03:04.649 276M / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:03:04.836 276M / 11G INFO General (simplification.cpp : 476) Average coverage = 36.9994
0:03:04.836 276M / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:04.836 276M / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/assembly_graph_with_scaffolds.gfa
0:03:06.026 276M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/before_rr.fasta
0:03:07.428 276M / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/assembly_graph.fastg
0:03:12.090 276M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/simplified_contigs.fasta
0:03:13.653 276M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/final_contigs.fasta
0:03:15.349 276M / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:15.349 276M / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/assembly_graph_with_scaffolds.gfa
0:03:16.560 276M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/before_rr.fasta
0:03:17.986 276M / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/assembly_graph.fastg
0:03:22.682 276M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/simplified_contigs.fasta
0:03:24.236 276M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K21/final_contigs.fasta
0:03:25.905 276M / 11G INFO General (launch.hpp : 149) SPAdes finished
0:03:26.752 80M / 11G INFO General (main.cpp : 109) Assembling time: 0 hours 3 minutes 26 seconds
Max read length detected as 100

== Running assembler: K33

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K33/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.001 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.001 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=33
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.001 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.074 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.077 8M / 12M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.101 8M / 12M INFO General (construction.cpp : 111) Max read length 100
0:00:00.101 8M / 12M INFO General (construction.cpp : 117) Average read length 99.9908
0:00:00.101 8M / 12M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.103 8M / 12M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:00:00.106 8M / 12M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.106 8M / 12M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:00:00.106 8M / 12M INFO General (kmer_splitters.hpp : 97) Using cell size of 83886
0:00:12.896 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 18840371 reads
0:00:20.106 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:00:20.106 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:42.133 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:00:42.133 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:45.535 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 42042243 kmers in total.
0:00:45.535 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:49.624 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:49.626 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:49.626 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:00:49.629 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:49.629 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:00:49.629 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 104857
0:01:00.151 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 42042243 kmers
0:01:00.151 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 42042243 kmers.
0:01:01.008 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:03.043 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 41766903 kmers in total.
0:01:03.043 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:07.071 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:08.322 84M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:11.030 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 19375528 bytes occupied (3.71117 bits per kmer).
0:01:11.065 124M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:12.710 124M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:12.712 124M / 11G INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping
0:01:12.712 124M / 11G INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K)
0:01:12.712 124M / 11G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping
0:01:15.966 124M / 11G INFO Early tip clipping (early_simplification.hpp : 184) 5489079 34-mers were removed by early tip clipper
0:01:15.966 124M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:16.017 124M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:01:17.995 156M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 821483 sequences extracted
0:01:18.949 156M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:01:19.494 156M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 3 loops collected
0:01:19.899 364M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:01:19.899 364M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:19.899 364M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:20.722 392M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 19504768 bytes occupied (3.71146 bits per kmer).
0:01:20.812 556M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:01:37.226 556M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:01:38.577 556M / 11G INFO General (construction.cpp : 464) Processed 1642849 edges
0:01:38.837 276M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:01:38.841 276M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 3
0:01:38.841 276M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 21
0:01:38.841 276M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 22. Coverage mad: 7.413
0:01:38.842 276M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:38.874 276M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:38.959 276M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:39.254 276M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:39.846 276M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:40.068 276M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 22.1546. Fitted coverage std. dev: 5.52433
0:01:40.069 276M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.95359
0:01:40.069 276M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 13
0:01:40.069 276M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 12
0:01:40.069 276M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 30672269
0:01:40.069 276M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 22.1546
0:01:40.070 276M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 12
0:01:40.070 276M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:01:40.070 276M / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:01:40.070 276M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:01:40.070 276M / 11G INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled
0:01:40.070 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:01:40.121 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 3 times
0:01:40.121 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:01:40.325 276M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 8085 times
0:01:40.325 276M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:01:44.767 300M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 141884 times
0:01:44.767 300M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:01:44.873 300M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 13216 times
0:01:44.925 296M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:01:44.925 296M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:01:44.925 296M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:01:44.925 296M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:01:44.925 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:44.986 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1563 times
0:01:44.986 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:52.139 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 27868 times
0:01:52.139 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:52.258 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1375 times
0:01:52.258 296M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:01:52.258 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:52.344 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 14 times
0:01:52.344 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:52.521 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 456 times
0:01:52.521 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:52.590 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2456 times
0:01:52.590 296M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:01:52.590 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:52.594 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 13 times
0:01:52.594 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:52.983 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 693 times
0:01:52.983 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:53.132 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 5556 times
0:01:53.132 296M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:01:53.132 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:53.143 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 19 times
0:01:53.143 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:53.933 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1600 times
0:01:53.933 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:53.991 296M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2088 times
0:01:53.991 296M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:01:53.991 296M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:54.004 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 8 times
0:01:54.004 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:54.325 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 739 times
0:01:54.325 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:54.358 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1220 times
0:01:54.358 292M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:01:54.358 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:54.363 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2 times
0:01:54.363 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:54.543 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 392 times
0:01:54.544 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:54.565 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 734 times
0:01:54.565 292M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:01:54.565 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:54.568 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:01:54.568 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:54.663 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 238 times
0:01:54.663 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:54.683 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 713 times
0:01:54.683 292M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:01:54.683 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:54.685 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2 times
0:01:54.685 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:54.756 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 158 times
0:01:54.756 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:54.782 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 931 times
0:01:54.782 292M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:01:54.782 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:54.783 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:01:54.783 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:54.872 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 192 times
0:01:54.872 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:54.910 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1335 times
0:01:54.910 292M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:01:54.911 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:54.912 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times
0:01:54.912 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:55.019 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 264 times
0:01:55.019 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:55.077 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2117 times
0:01:55.077 292M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:01:55.077 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:55.104 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times
0:01:55.104 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:55.678 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 416 times
0:01:55.678 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:55.714 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:01:55.714 292M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:01:55.714 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:55.717 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:01:55.717 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:55.717 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:01:55.717 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:55.717 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:01:55.717 292M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:01:55.717 292M / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:01:55.717 292M / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:01:55.717 292M / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:01:55.717 292M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:01:55.717 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:55.743 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:01:55.743 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:56.236 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1 times
0:01:56.236 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:56.264 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:01:56.264 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:56.759 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:01:56.759 292M / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:01:57.176 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:01:57.204 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 226 times
0:01:57.204 292M / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:01:57.403 292M / 11G INFO General (simplification.cpp : 476) Average coverage = 30.0416
0:01:57.403 292M / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:01:57.403 292M / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/assembly_graph_with_scaffolds.gfa
0:01:58.702 292M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/before_rr.fasta
0:02:00.287 292M / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/assembly_graph.fastg
0:02:05.276 292M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/simplified_contigs.fasta
0:02:06.860 292M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/final_contigs.fasta
0:02:08.626 292M / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:02:08.626 292M / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/assembly_graph_with_scaffolds.gfa
0:02:09.929 292M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/before_rr.fasta
0:02:11.565 292M / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/assembly_graph.fastg
0:02:16.756 292M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/simplified_contigs.fasta
0:02:18.615 292M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K33/final_contigs.fasta
0:02:20.507 292M / 11G INFO General (launch.hpp : 149) SPAdes finished
0:02:21.330 80M / 11G INFO General (main.cpp : 109) Assembling time: 0 hours 2 minutes 21 seconds

== Running assembler: K47

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K47/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=47
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.001 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.077 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.084 8M / 12M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.191 8M / 12M INFO General (construction.cpp : 111) Max read length 100
0:00:00.191 8M / 12M INFO General (construction.cpp : 117) Average read length 99.9908
0:00:00.191 8M / 12M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.200 8M / 12M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:00:00.204 8M / 12M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.204 8M / 12M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:00:00.205 8M / 12M INFO General (kmer_splitters.hpp : 97) Using cell size of 83886
0:00:13.196 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 24468700 reads
0:00:18.397 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:00:18.397 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:40.956 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:00:40.956 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:44.294 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 45592255 kmers in total.
0:00:44.294 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:48.872 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:48.874 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:48.874 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:00:48.877 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:48.877 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:00:48.877 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 104857
0:00:58.053 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 45592255 kmers
0:00:58.053 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 45592255 kmers.
0:00:58.918 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:01.400 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 45367514 kmers in total.
0:01:01.400 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:05.546 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:07.244 84M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:09.789 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21045144 bytes occupied (3.71105 bits per kmer).
0:01:09.828 128M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:11.712 128M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:11.714 128M / 11G INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping
0:01:11.714 128M / 11G INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K)
0:01:11.714 128M / 11G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping
0:01:15.481 128M / 11G INFO Early tip clipping (early_simplification.hpp : 184) 6141107 48-mers were removed by early tip clipper
0:01:15.481 128M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:15.534 128M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:01:17.756 156M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 762854 sequences extracted
0:01:18.887 156M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:01:19.479 156M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 2 loops collected
0:01:19.829 352M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:01:19.829 352M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:19.829 352M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:20.770 384M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21151504 bytes occupied (3.71142 bits per kmer).
0:01:20.864 560M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:01:35.055 556M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:01:36.539 556M / 11G INFO General (construction.cpp : 464) Processed 1525697 edges
0:01:36.795 268M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:01:36.796 268M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 2
0:01:36.797 268M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 16
0:01:36.797 268M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 17. Coverage mad: 5.9304
0:01:36.797 268M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:36.824 268M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:36.894 268M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:37.143 268M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:37.644 268M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:38.015 268M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 17.3667. Fitted coverage std. dev: 4.78741
0:01:38.016 268M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.930832
0:01:38.016 268M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 10
0:01:38.016 268M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 9
0:01:38.016 268M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 32272762
0:01:38.016 268M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 17.3667
0:01:38.016 268M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 9
0:01:38.016 268M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:01:38.016 268M / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:01:38.016 268M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:01:38.016 268M / 11G INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled
0:01:38.016 268M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:01:38.069 268M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:01:38.069 268M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:01:38.361 268M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 10750 times
0:01:38.361 268M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:01:42.805 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 118225 times
0:01:42.805 292M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:01:43.003 292M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 27708 times
0:01:43.052 288M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:01:43.052 288M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:01:43.052 288M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:01:43.052 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:01:43.052 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:43.141 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 4076 times
0:01:43.141 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:51.312 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 23374 times
0:01:51.312 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:51.483 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2389 times
0:01:51.483 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:01:51.483 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:51.571 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 7 times
0:01:51.571 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:51.902 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 552 times
0:01:51.902 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:51.907 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 109 times
0:01:51.907 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:01:51.907 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:51.909 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times
0:01:51.909 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:51.937 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 32 times
0:01:51.937 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:52.008 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2346 times
0:01:52.008 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:01:52.008 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:52.012 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 47 times
0:01:52.012 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:52.594 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 807 times
0:01:52.594 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:52.649 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1763 times
0:01:52.649 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:01:52.649 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:52.658 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 25 times
0:01:52.658 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:53.034 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 586 times
0:01:53.034 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:53.063 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 864 times
0:01:53.063 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:01:53.063 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:53.068 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 17 times
0:01:53.068 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:53.242 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 245 times
0:01:53.242 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:53.260 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 588 times
0:01:53.260 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:01:53.260 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:53.262 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2 times
0:01:53.262 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:53.350 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 146 times
0:01:53.350 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:53.373 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 724 times
0:01:53.373 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:01:53.373 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:53.375 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 6 times
0:01:53.375 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:53.463 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 133 times
0:01:53.464 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:53.496 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1016 times
0:01:53.496 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:01:53.496 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:53.497 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 3 times
0:01:53.497 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:53.601 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 158 times
0:01:53.601 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:53.650 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1520 times
0:01:53.650 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:01:53.650 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:53.652 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2 times
0:01:53.652 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:53.806 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 223 times
0:01:53.806 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:53.876 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2194 times
0:01:53.876 288M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:01:53.876 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:53.904 288M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 5 times
0:01:53.904 288M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:54.554 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 330 times
0:01:54.554 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:54.591 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:01:54.591 284M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:01:54.591 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:54.595 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:01:54.595 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:54.595 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:01:54.595 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:01:54.595 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:01:54.595 284M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:01:54.595 284M / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:01:54.595 284M / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:01:54.595 284M / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:01:54.595 284M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:01:54.595 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:54.622 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:01:54.622 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:55.201 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 2 times
0:01:55.201 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:01:55.233 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:01:55.233 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:01:55.812 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:01:55.812 284M / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:01:56.241 284M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:01:56.266 284M / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 41 times
0:01:56.266 284M / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:01:56.472 284M / 11G INFO General (simplification.cpp : 476) Average coverage = 22.6018
0:01:56.472 284M / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:01:56.472 284M / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/assembly_graph_with_scaffolds.gfa
0:01:57.799 284M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/before_rr.fasta
0:01:59.399 284M / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/assembly_graph.fastg
0:02:04.546 284M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/simplified_contigs.fasta
0:02:06.154 284M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/final_contigs.fasta
0:02:08.149 284M / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:02:08.149 284M / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/assembly_graph_with_scaffolds.gfa
0:02:09.667 284M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/before_rr.fasta
0:02:11.290 284M / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/assembly_graph.fastg
0:02:16.472 284M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/simplified_contigs.fasta
0:02:18.094 284M / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K47/final_contigs.fasta
0:02:19.975 284M / 11G INFO General (launch.hpp : 149) SPAdes finished
0:02:20.815 80M / 11G INFO General (main.cpp : 109) Assembling time: 0 hours 2 minutes 20 seconds

== Running assembler: K55

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K55/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.001 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.001 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.001 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=55
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.001 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.076 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.079 8M / 12M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.105 8M / 12M INFO General (construction.cpp : 111) Max read length 100
0:00:00.105 8M / 12M INFO General (construction.cpp : 117) Average read length 99.9908
0:00:00.105 8M / 12M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.108 8M / 12M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:00:00.110 8M / 12M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.110 8M / 12M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:00:00.110 8M / 12M INFO General (kmer_splitters.hpp : 97) Using cell size of 83886
0:00:13.899 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:00:13.899 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:37.186 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:00:37.186 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:40.582 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 47111950 kmers in total.
0:00:40.582 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:44.856 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:44.858 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:44.858 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:00:44.861 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:44.861 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:00:44.861 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 104857
0:00:54.106 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 47111950 kmers
0:00:54.106 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 47111950 kmers.
0:00:54.979 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:57.365 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 46948218 kmers in total.
0:00:57.365 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:01.614 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:03.018 84M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:06.377 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21778032 bytes occupied (3.71099 bits per kmer).
0:01:06.412 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:08.433 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:08.437 132M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:08.495 132M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:01:11.180 244M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1464724 sequences extracted
0:01:12.438 244M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:01:13.014 244M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:01:13.650 584M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:01:13.650 584M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:13.650 584M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:14.506 600M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21861648 bytes occupied (3.71229 bits per kmer).
0:01:14.603 780M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:01:26.856 780M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:01:28.703 780M / 11G INFO General (construction.cpp : 464) Processed 2929440 edges
0:01:28.984 524M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:01:28.985 524M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:01:28.985 524M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 13
0:01:28.985 524M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 14. Coverage mad: 5.9304
0:01:28.985 524M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:29.007 524M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:29.064 524M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:29.257 524M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:29.643 520M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:30.138 516M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 14.6449. Fitted coverage std. dev: 4.33651
0:01:30.139 516M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.999003
0:01:30.139 516M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 8
0:01:30.139 516M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 7
0:01:30.139 516M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 33316712
0:01:30.139 516M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 14.6449
0:01:30.139 516M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 7
0:01:30.139 516M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:01:30.139 516M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:01:30.139 516M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:01:30.144 516M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:30.144 516M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:01:30.147 516M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:01:30.147 516M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0583 Gb
0:01:30.147 516M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 104857
0:01:38.045 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 2929440 edges
0:01:38.046 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 2929440 sequences.
0:01:38.793 500M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:41.312 500M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 47111950 kmers in total.
0:01:41.313 500M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:45.581 500M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:47.312 532M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:49.948 532M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 21853864 bytes occupied (3.71097 bits per kmer).
0:01:50.518 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:01:51.726 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:01:51.735 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:01:53.821 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:01:58.496 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:01:58.496 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:01:58.809 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:02:03.254 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 32 gaps after checking 1432 candidates
0:02:03.335 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:02:03.342 524M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:02:03.343 524M / 11G INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled
0:02:03.343 524M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:02:03.454 524M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:02:03.454 524M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:02:12.112 548M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 413512 times
0:02:12.112 548M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:02:16.080 540M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 89317 times
0:02:16.080 540M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:02:16.411 536M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 49749 times
0:02:16.472 536M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:02:16.473 536M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:02:16.473 536M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:02:16.473 536M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:02:16.473 536M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:16.574 532M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 4481 times
0:02:16.574 532M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:32.121 652M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 21159 times
0:02:32.121 652M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:32.348 652M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 3085 times
0:02:32.348 652M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:02:32.348 652M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:32.438 652M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 10 times
0:02:32.438 652M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:33.132 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 665 times
0:02:33.132 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:33.135 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 53 times
0:02:33.135 656M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:02:33.135 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:33.138 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:02:33.138 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:33.160 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 18 times
0:02:33.160 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:33.166 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 189 times
0:02:33.166 656M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:02:33.166 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:33.166 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 5 times
0:02:33.166 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:33.239 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 66 times
0:02:33.239 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:33.283 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1302 times
0:02:33.283 656M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:02:33.283 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:33.286 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 64 times
0:02:33.286 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:33.821 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 456 times
0:02:33.821 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:33.850 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 824 times
0:02:33.850 660M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:02:33.850 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:33.855 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 22 times
0:02:33.855 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:34.091 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 208 times
0:02:34.091 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:34.111 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 579 times
0:02:34.111 660M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:02:34.111 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:34.113 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 13 times
0:02:34.113 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:34.263 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 125 times
0:02:34.263 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:34.285 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 591 times
0:02:34.286 660M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:02:34.286 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:34.287 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 12 times
0:02:34.287 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:34.422 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 109 times
0:02:34.422 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:34.452 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 854 times
0:02:34.452 660M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:02:34.452 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:34.454 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 11 times
0:02:34.454 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:34.583 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 107 times
0:02:34.583 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:34.624 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1137 times
0:02:34.624 664M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:02:34.624 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:34.626 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 10 times
0:02:34.626 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:34.767 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 125 times
0:02:34.767 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:34.831 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1773 times
0:02:34.831 664M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:02:34.831 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:34.861 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 9 times
0:02:34.861 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:35.600 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 241 times
0:02:35.600 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:35.638 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:02:35.638 656M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:02:35.638 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:35.640 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:02:35.640 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:35.640 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:02:35.640 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:35.640 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:02:35.640 656M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:02:35.640 656M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:02:35.646 656M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:02:35.646 656M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:02:35.648 656M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:02:35.648 656M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.056 Gb
0:02:35.648 656M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 104857
0:02:42.665 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 522943 edges
0:02:42.665 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 522943 sequences.
0:02:43.382 648M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:02:45.601 648M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 33590903 kmers in total.
0:02:45.601 648M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:02:49.038 648M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:49.756 680M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:02:51.759 680M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 15583976 bytes occupied (3.71148 bits per kmer).
0:02:52.288 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:02:53.042 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:02:53.053 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:02:53.346 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:02:59.671 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:02:59.672 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:02:59.672 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:03:00.350 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 1 gaps after checking 16 candidates
0:03:00.386 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:03:00.387 1G / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:03:00.387 1G / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:03:00.387 1G / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:03:00.387 1G / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:03:00.387 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.417 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:00.417 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:01.006 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:01.006 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:01.036 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:01.036 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:01.633 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:01.633 1G / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:03:02.085 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:03:02.116 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 17 times
0:03:02.117 1G / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:03:02.323 1G / 11G INFO General (simplification.cpp : 476) Average coverage = 18.6392
0:03:02.323 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:02.323 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/assembly_graph_with_scaffolds.gfa
0:03:03.704 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/before_rr.fasta
0:03:05.409 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/assembly_graph.fastg
0:03:10.813 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/simplified_contigs.fasta
0:03:12.695 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/final_contigs.fasta
0:03:14.628 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:14.628 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/assembly_graph_with_scaffolds.gfa
0:03:16.052 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/before_rr.fasta
0:03:17.780 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/assembly_graph.fastg
0:03:23.095 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/simplified_contigs.fasta
0:03:24.869 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K55/final_contigs.fasta
0:03:26.841 1G / 11G INFO General (launch.hpp : 149) SPAdes finished
0:03:29.086 80M / 11G INFO General (main.cpp : 109) Assembling time: 0 hours 3 minutes 29 seconds

== Running assembler: K59

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K59/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=59
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.001 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.077 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.079 8M / 12M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.098 8M / 12M INFO General (construction.cpp : 111) Max read length 100
0:00:00.098 8M / 12M INFO General (construction.cpp : 117) Average read length 99.9908
0:00:00.098 8M / 12M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.101 8M / 12M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:00:00.103 8M / 12M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.103 8M / 12M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:00:00.103 8M / 12M INFO General (kmer_splitters.hpp : 97) Using cell size of 83886
0:00:14.602 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:00:14.602 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:38.134 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:00:38.134 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:41.883 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 47674667 kmers in total.
0:00:41.883 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:46.746 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:46.749 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:46.749 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:00:46.752 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:46.752 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:00:46.752 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 104857
0:00:56.253 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 47674667 kmers
0:00:56.253 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 47674667 kmers.
0:00:57.115 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:59.662 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 47547352 kmers in total.
0:00:59.662 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:04.193 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:05.653 84M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:08.475 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22056024 bytes occupied (3.711 bits per kmer).
0:01:08.516 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:10.579 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:10.582 132M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:10.651 132M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:01:13.724 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1423057 sequences extracted
0:01:15.045 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:01:15.656 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:01:16.299 568M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:01:16.299 568M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:16.299 568M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:17.364 592M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22116752 bytes occupied (3.71128 bits per kmer).
0:01:17.461 776M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:01:28.909 772M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:01:30.738 772M / 11G INFO General (construction.cpp : 464) Processed 2846108 edges
0:01:30.986 508M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:01:30.987 508M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:01:30.987 508M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 12
0:01:30.987 508M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 13. Coverage mad: 5.9304
0:01:30.987 508M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:31.006 508M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:31.060 508M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:31.243 508M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:31.616 508M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:31.979 508M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 13.2974. Fitted coverage std. dev: 4.09982
0:01:31.979 508M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.998317
0:01:31.980 508M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 7
0:01:31.980 508M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 6
0:01:31.980 508M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 33856047
0:01:31.980 508M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 13.2974
0:01:31.980 508M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 6
0:01:31.980 508M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:01:31.980 508M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:01:31.980 508M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:01:31.985 508M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:31.985 508M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:01:31.988 508M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:01:31.988 508M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0584 Gb
0:01:31.988 508M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 104857
0:01:40.444 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 2846108 edges
0:01:40.444 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 2846108 sequences.
0:01:41.183 504M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:43.720 504M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 47674667 kmers in total.
0:01:43.720 504M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:48.812 504M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:50.535 516M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:53.798 516M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22115056 bytes occupied (3.71099 bits per kmer).
0:01:54.363 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:01:55.587 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:01:55.595 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:01:57.684 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:02:01.975 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:02:01.976 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:02:02.309 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:02:06.526 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 27 gaps after checking 1541 candidates
0:02:06.606 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:02:06.613 512M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:02:06.613 512M / 11G INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled
0:02:06.613 512M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:02:06.727 512M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:02:06.728 512M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:02:15.212 544M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 406407 times
0:02:15.212 544M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:02:18.624 544M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 76884 times
0:02:18.624 544M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:02:19.050 540M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 68969 times
0:02:19.106 540M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:02:19.106 540M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:02:19.106 540M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:02:19.106 540M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:02:19.106 540M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:19.197 540M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 3814 times
0:02:19.197 540M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:34.620 656M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 20043 times
0:02:34.620 656M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:34.851 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 3444 times
0:02:34.851 660M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:02:34.851 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:34.936 660M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 9 times
0:02:34.936 660M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:35.788 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 719 times
0:02:35.788 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:35.790 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 41 times
0:02:35.790 668M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:02:35.790 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:35.794 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times
0:02:35.794 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:35.814 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 15 times
0:02:35.814 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:35.815 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 31 times
0:02:35.815 668M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:02:35.815 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:35.815 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times
0:02:35.815 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:35.821 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 3 times
0:02:35.821 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:35.841 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 584 times
0:02:35.841 668M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:02:35.841 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:35.842 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 39 times
0:02:35.842 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:36.076 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 206 times
0:02:36.076 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:36.104 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 837 times
0:02:36.104 664M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:02:36.104 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:36.107 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 35 times
0:02:36.107 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:36.340 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 215 times
0:02:36.340 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:36.356 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 423 times
0:02:36.356 664M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:02:36.356 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:36.357 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 11 times
0:02:36.357 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:36.462 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 85 times
0:02:36.462 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:36.483 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 607 times
0:02:36.483 664M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:02:36.483 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:36.484 664M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 14 times
0:02:36.484 664M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:36.607 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 106 times
0:02:36.607 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:36.629 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 635 times
0:02:36.629 668M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:02:36.629 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:36.630 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 10 times
0:02:36.630 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:36.736 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 83 times
0:02:36.736 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:36.772 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 977 times
0:02:36.772 668M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:02:36.772 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:36.773 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 11 times
0:02:36.773 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:36.898 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 99 times
0:02:36.898 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:36.950 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1486 times
0:02:36.950 668M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:02:36.950 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:36.979 668M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 8 times
0:02:36.979 668M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:37.681 652M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 185 times
0:02:37.681 652M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:37.717 652M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:02:37.717 652M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:02:37.717 652M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:37.718 652M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:02:37.718 652M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:37.718 652M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:02:37.718 652M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:37.718 652M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:02:37.718 652M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:02:37.718 652M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:02:37.728 652M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:02:37.728 652M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:02:37.730 652M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:02:37.730 652M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0561 Gb
0:02:37.730 652M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 104857
0:02:44.940 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 511745 edges
0:02:44.940 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 511745 sequences.
0:02:45.692 652M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:02:48.005 652M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 34031375 kmers in total.
0:02:48.005 652M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:02:51.556 652M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:52.249 680M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:02:54.843 680M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 15788488 bytes occupied (3.71151 bits per kmer).
0:02:55.405 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:02:56.143 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:02:56.154 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:02:56.447 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:03:02.317 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:03:02.318 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:03:02.318 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:03:02.958 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 2 gaps after checking 7 candidates
0:03:03.003 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:03:03.003 1G / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:03:03.003 1G / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:03:03.003 1G / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:03:03.003 1G / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:03:03.003 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:03.034 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:03.034 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:03.598 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:03.598 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:03.636 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:03.636 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:04.199 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:04.199 1G / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:03:04.643 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:03:04.672 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 14 times
0:03:04.672 1G / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:03:04.874 1G / 11G INFO General (simplification.cpp : 476) Average coverage = 16.7417
0:03:04.874 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:04.874 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/assembly_graph_with_scaffolds.gfa
0:03:06.249 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/before_rr.fasta
0:03:07.938 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/assembly_graph.fastg
0:03:13.280 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/simplified_contigs.fasta
0:03:14.936 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/final_contigs.fasta
0:03:16.901 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:16.901 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/assembly_graph_with_scaffolds.gfa
0:03:18.442 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/before_rr.fasta
0:03:20.203 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/assembly_graph.fastg
0:03:25.501 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/simplified_contigs.fasta
0:03:27.161 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K59/final_contigs.fasta
0:03:29.035 1G / 11G INFO General (launch.hpp : 149) SPAdes finished
0:03:31.263 80M / 11G INFO General (main.cpp : 109) Assembling time: 0 hours 3 minutes 31 seconds

== Running assembler: K65

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K65/configs/config.info
0:00:00.001 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.001 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.001 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.001 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=65
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.002 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.002 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.002 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.085 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.087 8M / 12M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.106 8M / 12M INFO General (construction.cpp : 111) Max read length 100
0:00:00.106 8M / 12M INFO General (construction.cpp : 117) Average read length 99.9908
0:00:00.106 8M / 12M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.109 8M / 12M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:00:00.111 8M / 12M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.111 8M / 12M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:00:00.111 8M / 12M INFO General (kmer_splitters.hpp : 97) Using cell size of 55924
0:00:14.248 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 24540761 reads
0:00:20.276 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:00:20.276 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:50.870 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:00:50.870 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:55.273 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48239510 kmers in total.
0:00:55.273 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:02.129 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:01:02.132 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:02.132 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:01:02.134 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:01:02.134 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:01:02.134 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:01:13.308 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 48239510 kmers
0:01:13.308 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 48239510 kmers.
0:01:14.809 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:17.552 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48169771 kmers in total.
0:01:17.552 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:23.474 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:25.452 84M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:30.223 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22344624 bytes occupied (3.71098 bits per kmer).
0:01:30.264 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:32.379 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:32.382 132M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:32.496 132M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:01:35.531 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1355112 sequences extracted
0:01:36.945 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:01:37.493 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:01:38.135 540M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:01:38.135 540M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:38.135 540M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:39.311 584M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22378864 bytes occupied (3.71129 bits per kmer).
0:01:39.411 772M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:01:49.563 772M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:01:51.515 772M / 11G INFO General (construction.cpp : 464) Processed 2710221 edges
0:01:51.857 496M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:01:51.858 496M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:01:51.858 496M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 10
0:01:51.858 496M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 11. Coverage mad: 5.9304
0:01:51.858 496M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:51.875 496M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:51.919 496M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:52.069 496M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:52.379 496M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:52.845 484M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 11.2948. Fitted coverage std. dev: 3.72838
0:01:52.845 484M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.996066
0:01:52.845 484M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 6
0:01:52.845 484M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 5
0:01:52.845 484M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 34351498
0:01:52.846 484M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 11.2948
0:01:52.846 484M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 5
0:01:52.846 484M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:01:52.846 484M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:01:52.846 484M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:01:52.852 484M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:52.852 484M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:01:52.854 484M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:01:52.854 484M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0588 Gb
0:01:52.854 484M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:02:02.479 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 2710221 edges
0:02:02.479 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 2710221 sequences.
0:02:03.236 480M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:02:05.980 480M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48239510 kmers in total.
0:02:05.980 480M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:02:12.169 480M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:14.216 492M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:02:19.792 492M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22376928 bytes occupied (3.71097 bits per kmer).
0:02:20.354 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:02:21.600 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:02:21.608 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:02:23.624 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:02:27.428 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:02:27.428 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:02:27.777 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:02:31.722 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 38 gaps after checking 1575 candidates
0:02:31.807 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:02:31.817 492M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:02:31.817 492M / 11G INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled
0:02:31.817 492M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:02:31.929 492M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:02:31.929 492M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:02:39.808 524M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 381882 times
0:02:39.808 524M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:02:42.700 524M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 63458 times
0:02:42.701 524M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:02:43.321 520M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 105500 times
0:02:43.371 516M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:02:43.371 516M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:02:43.371 516M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:02:43.371 516M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:02:43.371 516M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:43.448 512M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2857 times
0:02:43.448 512M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:58.642 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 18445 times
0:02:58.642 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:58.891 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 3971 times
0:02:58.891 732M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:02:58.891 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:58.970 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 16 times
0:02:58.970 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.935 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 794 times
0:02:59.935 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.938 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 39 times
0:02:59.938 740M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:02:59.938 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.942 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 4 times
0:02:59.942 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.958 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 12 times
0:02:59.958 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.959 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 30 times
0:02:59.959 740M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:02:59.959 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.959 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 3 times
0:02:59.959 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.964 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 5 times
0:02:59.964 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.965 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 17 times
0:02:59.965 740M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:02:59.965 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.965 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:02:59.965 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.965 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1 times
0:02:59.965 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.981 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 488 times
0:02:59.981 740M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:02:59.981 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.981 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 30 times
0:02:59.981 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.151 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 130 times
0:03:00.151 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.172 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 609 times
0:03:00.172 740M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:03:00.172 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.173 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 37 times
0:03:00.173 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.296 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 100 times
0:03:00.296 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.311 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 462 times
0:03:00.311 744M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:03:00.311 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.312 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 16 times
0:03:00.312 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.406 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 70 times
0:03:00.406 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.430 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 778 times
0:03:00.430 744M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:03:00.430 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.431 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 9 times
0:03:00.431 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.547 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 81 times
0:03:00.547 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.575 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 770 times
0:03:00.575 744M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:03:00.575 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.576 744M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 11 times
0:03:00.576 744M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.688 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 90 times
0:03:00.688 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.733 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1364 times
0:03:00.733 740M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:03:00.734 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.762 740M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 10 times
0:03:00.762 740M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:01.411 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 153 times
0:03:01.411 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:01.453 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:01.453 732M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:03:01.453 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:01.454 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:01.454 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:01.454 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:01.454 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:01.455 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:01.455 732M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:03:01.455 732M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:03:01.460 732M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:03:01.460 732M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:03:01.462 732M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:03:01.462 732M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0548 Gb
0:03:01.462 732M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:03:09.602 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 482999 edges
0:03:09.603 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 482999 sequences.
0:03:10.365 732M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:03:12.842 732M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 34655115 kmers in total.
0:03:12.842 732M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:03:17.409 732M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:03:18.632 764M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:03:22.197 764M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 16077600 bytes occupied (3.71145 bits per kmer).
0:03:22.835 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:03:23.588 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:03:23.598 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:03:23.874 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:03:29.119 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:03:29.119 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:03:29.120 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:03:29.677 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 10 candidates
0:03:29.710 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:03:29.710 1G / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:03:29.710 1G / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:03:29.710 1G / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:03:29.710 1G / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:03:29.710 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:29.739 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:29.739 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:30.299 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 2 times
0:03:30.299 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:30.336 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:30.336 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:30.871 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:30.871 1G / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:03:31.267 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:03:31.294 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 16 times
0:03:31.294 1G / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:03:31.485 1G / 11G INFO General (simplification.cpp : 476) Average coverage = 14.0024
0:03:31.485 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:31.485 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/assembly_graph_with_scaffolds.gfa
0:03:32.804 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/before_rr.fasta
0:03:34.382 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/assembly_graph.fastg
0:03:39.505 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/simplified_contigs.fasta
0:03:41.092 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/final_contigs.fasta
0:03:42.957 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:42.957 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/assembly_graph_with_scaffolds.gfa
0:03:44.501 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/before_rr.fasta
0:03:46.113 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/assembly_graph.fastg
0:03:51.316 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/simplified_contigs.fasta
0:03:52.935 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K65/final_contigs.fasta
0:03:54.821 1G / 11G INFO General (launch.hpp : 149) SPAdes finished
0:03:57.141 80M / 11G INFO General (main.cpp : 109) Assembling time: 0 hours 3 minutes 57 seconds

== Running assembler: K67

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K67/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=67
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.001 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.078 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.082 8M / 12M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.101 8M / 12M INFO General (construction.cpp : 111) Max read length 100
0:00:00.101 8M / 12M INFO General (construction.cpp : 117) Average read length 99.9908
0:00:00.101 8M / 12M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.103 8M / 12M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:00:00.106 8M / 12M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.106 8M / 12M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:00:00.106 8M / 12M INFO General (kmer_splitters.hpp : 97) Using cell size of 55924
0:00:14.326 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 25999252 reads
0:00:19.140 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:00:19.140 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:49.412 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:00:49.412 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:53.438 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48346910 kmers in total.
0:00:53.438 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:59.673 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:59.676 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:59.676 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:00:59.678 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:59.678 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:00:59.678 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:01:12.306 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 48346910 kmers
0:01:12.306 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 48346910 kmers.
0:01:13.715 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:16.562 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48296997 kmers in total.
0:01:16.562 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:22.859 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:25.080 84M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:29.452 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22403536 bytes occupied (3.71096 bits per kmer).
0:01:29.497 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:31.629 132M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:31.632 132M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:31.707 132M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:01:34.526 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1331576 sequences extracted
0:01:35.951 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:01:36.570 240M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:01:37.227 544M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:01:37.227 544M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:37.227 544M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:38.384 584M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22428816 bytes occupied (3.71131 bits per kmer).
0:01:38.490 772M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:01:48.120 772M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:01:50.051 772M / 11G INFO General (construction.cpp : 464) Processed 2663150 edges
0:01:50.394 480M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:01:50.395 480M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:01:50.395 480M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 9
0:01:50.395 480M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 10. Coverage mad: 5.9304
0:01:50.395 480M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:50.412 480M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:50.453 480M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:50.597 480M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:50.878 480M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:51.248 464M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 10.6321. Fitted coverage std. dev: 3.59792
0:01:51.248 464M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.994697
0:01:51.248 464M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 6
0:01:51.248 464M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 5
0:01:51.248 464M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 34197032
0:01:51.248 464M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 10.6321
0:01:51.248 464M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 5
0:01:51.248 464M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:01:51.248 464M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:01:51.248 464M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:01:51.254 464M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:51.254 464M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:01:51.257 464M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:01:51.257 464M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0591 Gb
0:01:51.257 464M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:02:00.947 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 2663150 edges
0:02:00.947 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 2663150 sequences.
0:02:01.718 460M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:02:04.550 460M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48346910 kmers in total.
0:02:04.550 460M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:02:10.889 460M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:12.972 500M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:02:18.245 500M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22426724 bytes occupied (3.71097 bits per kmer).
0:02:18.818 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:02:20.074 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:02:20.083 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:02:22.166 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:02:25.812 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:02:25.812 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:02:26.183 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:02:30.361 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 42 gaps after checking 1574 candidates
0:02:30.478 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:02:30.491 484M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:02:30.491 484M / 11G INFO General (graph_simplification.hpp : 662) Flanking coverage based disconnection disabled
0:02:30.491 484M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:02:30.619 484M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:02:30.619 484M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper
0:02:38.779 512M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 371007 times
0:02:38.779 512M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover
0:02:41.643 516M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 59981 times
0:02:41.643 516M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover
0:02:42.383 500M / 11G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 119177 times
0:02:42.433 496M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:02:42.433 496M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:02:42.433 496M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:02:42.433 496M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:02:42.433 496M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:42.509 492M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2552 times
0:02:42.509 492M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:58.084 716M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 17899 times
0:02:58.084 716M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:58.363 712M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 4156 times
0:02:58.363 712M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:02:58.363 712M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:58.442 712M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 17 times
0:02:58.442 712M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.364 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 809 times
0:02:59.364 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.366 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 38 times
0:02:59.366 724M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:02:59.366 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.370 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 3 times
0:02:59.370 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.382 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 9 times
0:02:59.382 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.383 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 27 times
0:02:59.383 724M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:02:59.383 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.383 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:02:59.383 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.386 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 3 times
0:02:59.386 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.386 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 22 times
0:02:59.386 724M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:02:59.386 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.386 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:02:59.386 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.388 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 3 times
0:02:59.388 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.406 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 487 times
0:02:59.406 724M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:02:59.406 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.407 724M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 32 times
0:02:59.407 724M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.537 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 103 times
0:02:59.537 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.558 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 621 times
0:02:59.558 728M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:02:59.558 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.560 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 38 times
0:02:59.560 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.687 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 87 times
0:02:59.687 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.705 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 531 times
0:02:59.705 728M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:02:59.705 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.706 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 12 times
0:02:59.706 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.804 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 63 times
0:02:59.804 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:59.839 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 969 times
0:02:59.839 728M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:02:59.839 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:59.840 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 16 times
0:02:59.840 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:59.986 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 96 times
0:02:59.986 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.022 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 960 times
0:03:00.022 728M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:03:00.023 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.024 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 7 times
0:03:00.024 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.183 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 116 times
0:03:00.183 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.244 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1679 times
0:03:00.244 728M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:03:00.244 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.272 728M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 9 times
0:03:00.272 728M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.921 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 164 times
0:03:00.921 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.954 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:00.954 732M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:03:00.954 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:00.956 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:00.956 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:00.956 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:00.956 732M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:03:00.956 732M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:03:00.956 732M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:03:00.956 732M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:03:00.961 732M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:03:00.961 732M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:03:00.964 732M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:03:00.964 732M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0548 Gb
0:03:00.964 732M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:03:09.264 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 465886 edges
0:03:09.264 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 465886 sequences.
0:03:10.032 732M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:03:12.529 732M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 34817551 kmers in total.
0:03:12.529 732M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:03:17.516 732M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:03:18.998 748M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:03:22.425 748M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 16153336 bytes occupied (3.71154 bits per kmer).
0:03:23.094 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:03:23.942 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:03:23.951 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:03:24.211 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:03:29.245 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:03:29.246 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:03:29.246 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:03:29.810 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 2 gaps after checking 17 candidates
0:03:29.851 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:03:29.851 1G / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:03:29.851 1G / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:03:29.851 1G / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:03:29.851 1G / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:03:29.851 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:29.880 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:29.880 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:30.422 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 2 times
0:03:30.422 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:30.450 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:30.450 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:30.977 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:30.977 1G / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:03:31.369 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:03:31.397 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 11 times
0:03:31.397 1G / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:03:31.581 1G / 11G INFO General (simplification.cpp : 476) Average coverage = 13.125
0:03:31.581 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:31.581 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/assembly_graph_with_scaffolds.gfa
0:03:32.929 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/before_rr.fasta
0:03:34.631 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/assembly_graph.fastg
0:03:39.954 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/simplified_contigs.fasta
0:03:41.800 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/final_contigs.fasta
0:03:43.585 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:43.585 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/assembly_graph_with_scaffolds.gfa
0:03:45.082 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/before_rr.fasta
0:03:46.802 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/assembly_graph.fastg
0:03:52.269 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/simplified_contigs.fasta
0:03:53.873 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K67/final_contigs.fasta
0:03:55.653 1G / 11G INFO General (launch.hpp : 149) SPAdes finished
0:03:58.288 80M / 11G INFO General (main.cpp : 109) Assembling time: 0 hours 3 minutes 58 seconds

sunnycqcn · 2019-07-30T18:51:57Z

== Running assembler: K73

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K73/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.001 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.001 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=73
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.001 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.077 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.079 8M / 12M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.099 8M / 12M INFO General (construction.cpp : 111) Max read length 100
0:00:00.099 8M / 12M INFO General (construction.cpp : 117) Average read length 99.9908
0:00:00.099 8M / 12M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.101 8M / 12M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:00:00.103 8M / 12M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.103 8M / 12M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:00:00.103 8M / 12M INFO General (kmer_splitters.hpp : 97) Using cell size of 55924
0:00:13.892 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:00:13.892 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:43.624 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:00:43.624 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:47.548 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48411849 kmers in total.
0:00:47.548 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:54.227 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:54.230 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:54.230 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:00:54.232 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:54.232 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:00:54.232 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:01:05.730 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 48411849 kmers
0:01:05.730 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 48411849 kmers.
0:01:07.168 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:09.985 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48429788 kmers in total.
0:01:09.985 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:15.816 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:17.655 88M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:21.488 88M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22465160 bytes occupied (3.71097 bits per kmer).
0:01:21.530 136M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:23.649 136M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:23.653 132M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:23.716 136M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:01:26.562 236M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1251118 sequences extracted
0:01:27.977 236M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:01:28.595 236M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:01:29.227 540M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:01:29.227 540M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:29.227 540M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:30.616 564M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22458856 bytes occupied (3.7113 bits per kmer).
0:01:30.715 752M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:01:38.928 752M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:01:40.829 752M / 11G INFO General (construction.cpp : 464) Processed 2502235 edges
0:01:41.142 460M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:01:41.143 460M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:01:41.143 460M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 7
0:01:41.143 460M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 8. Coverage mad: 4.4478
0:01:41.143 460M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:41.155 460M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:41.186 460M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:41.298 460M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:41.533 460M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:41.624 456M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 8.70733. Fitted coverage std. dev: 3.18557
0:01:41.625 456M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.988283
0:01:41.625 456M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 5
0:01:41.625 456M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 4
0:01:41.625 456M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 34488108
0:01:41.625 456M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 8.70733
0:01:41.625 456M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 4
0:01:41.625 456M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:01:41.625 456M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:01:41.625 456M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:01:41.629 456M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:41.629 456M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:01:41.632 456M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:01:41.632 456M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0592 Gb
0:01:41.632 456M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:01:51.226 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 2502235 edges
0:01:51.226 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 2502235 sequences.
0:01:51.809 444M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:54.600 444M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48411849 kmers in total.
0:01:54.600 444M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:02:00.604 444M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:02.511 492M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:02:06.282 492M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22456792 bytes occupied (3.71096 bits per kmer).
0:02:06.842 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:02:08.066 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:02:08.076 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:02:10.077 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:02:13.145 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:02:13.145 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:02:13.550 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:02:17.356 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 70 gaps after checking 1577 candidates
0:02:17.449 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:02:17.460 460M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:02:17.460 460M / 11G INFO General (simplification.cpp : 68) Most init cleaning disabled since detected mean 8.70733 was less than activation coverage 10
0:02:17.460 460M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:02:17.568 460M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:02:17.568 460M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:02:17.568 460M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:02:17.568 460M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:02:17.568 460M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:02:17.568 460M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:23.984 480M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 326899 times
0:02:23.984 480M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:43.956 804M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 26617 times
0:02:43.956 804M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:45.545 808M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 30184 times
0:02:45.545 808M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:02:45.545 808M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:45.648 808M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 105 times
0:02:45.648 808M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:48.866 856M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 2978 times
0:02:48.866 856M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:48.918 856M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1157 times
0:02:48.918 856M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:02:48.918 856M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:48.943 856M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 14 times
0:02:48.943 856M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:49.219 860M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 187 times
0:02:49.219 860M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:49.510 856M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 7430 times
0:02:49.510 856M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:02:49.510 856M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:49.547 856M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1167 times
0:02:49.547 856M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:51.553 884M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1638 times
0:02:51.553 884M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:51.583 884M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 726 times
0:02:51.583 884M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:02:51.583 884M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:51.600 884M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 77 times
0:02:51.600 884M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:51.834 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 158 times
0:02:51.835 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:51.874 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 964 times
0:02:51.874 888M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:02:51.874 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:51.878 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 75 times
0:02:51.878 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:52.148 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 174 times
0:02:52.148 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:52.164 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 397 times
0:02:52.164 888M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:02:52.164 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:52.166 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 23 times
0:02:52.166 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:52.282 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 60 times
0:02:52.282 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:52.303 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 540 times
0:02:52.303 888M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:02:52.303 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:52.304 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 24 times
0:02:52.304 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:52.410 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 57 times
0:02:52.410 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:52.445 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 923 times
0:02:52.445 892M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:02:52.445 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:52.447 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 20 times
0:02:52.447 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:52.582 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 78 times
0:02:52.582 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:52.621 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 964 times
0:02:52.621 892M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:02:52.621 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:52.623 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 7 times
0:02:52.623 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:52.753 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 94 times
0:02:52.753 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:52.814 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1601 times
0:02:52.814 892M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:02:52.814 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:52.886 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 63 times
0:02:52.886 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:53.559 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 177 times
0:02:53.559 896M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:53.629 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:02:53.629 896M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:02:53.629 896M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:53.630 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:02:53.630 896M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:53.630 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:02:53.630 896M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:53.630 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:02:53.630 896M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:02:53.630 896M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:02:53.637 896M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:02:53.637 896M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:02:53.639 896M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:02:53.639 896M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0521 Gb
0:02:53.639 896M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:03:02.215 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 778713 edges
0:03:02.215 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 778713 sequences.
0:03:02.969 896M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:03:05.533 896M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 39847350 kmers in total.
0:03:05.533 896M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:03:10.912 896M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:03:12.538 928M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:03:15.615 928M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 18485256 bytes occupied (3.71121 bits per kmer).
0:03:16.316 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:03:17.282 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:03:17.291 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:03:18.188 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:03:22.647 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:03:22.647 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:03:22.821 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:03:23.891 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 0 gaps after checking 459 candidates
0:03:23.973 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:03:23.974 1G / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:03:23.974 1G / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:03:23.974 1G / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:03:23.974 1G / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:03:23.974 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:24.058 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:24.058 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:24.595 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1 times
0:03:24.595 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:24.658 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:24.658 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:25.177 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:25.177 1G / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:03:25.867 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:03:31.103 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 170234 times
0:03:31.103 1G / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:03:31.280 1G / 11G INFO General (simplification.cpp : 476) Average coverage = 10.589
0:03:31.280 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:31.280 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/assembly_graph_with_scaffolds.gfa
0:03:32.540 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/before_rr.fasta
0:03:34.035 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/assembly_graph.fastg
0:03:38.823 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/simplified_contigs.fasta
0:03:40.345 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/final_contigs.fasta
0:03:42.008 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Contig Output
0:03:42.008 1G / 11G INFO General (contig_output_stage.cpp : 40) Writing GFA to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/assembly_graph_with_scaffolds.gfa
0:03:43.293 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/before_rr.fasta
0:03:44.836 1G / 11G INFO General (contig_output_stage.cpp : 51) Outputting FastG graph to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/assembly_graph.fastg
0:03:49.695 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/simplified_contigs.fasta
0:03:51.237 1G / 11G INFO General (contig_output.hpp : 22) Outputting contigs to /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta//K73/final_contigs.fasta
0:03:53.072 1G / 11G INFO General (launch.hpp : 149) SPAdes finished
0:03:56.117 80M / 11G INFO General (main.cpp : 109) Assembling time: 0 hours 3 minutes 56 seconds

== Running assembler: K77

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K77/configs/config.info
0:00:00.001 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 1024 Gb
0:00:00.001 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea4665
0:00:00.001 4M / 4M INFO General (main.cpp : 88) Maximum k-mer length: 128
0:00:00.001 4M / 4M INFO General (main.cpp : 89) Assembling dataset (/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/dataset.info) with K=77
0:00:00.001 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 20
0:00:00.001 4M / 4M INFO General (launch.hpp : 51) SPAdes started
0:00:00.001 4M / 4M INFO General (launch.hpp : 58) Starting from stage: construction
0:00:00.001 4M / 4M INFO General (launch.hpp : 65) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO General (launch.hpp : 76) Will need read mapping, kmer mapper will be attached
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction
0:00:00.078 8M / 12M INFO General (construction.cpp : 77) Trusted contigs will be used in graph construction
0:00:00.081 8M / 12M INFO General (read_converter.hpp : 59) Binary reads detected
0:00:00.103 8M / 12M INFO General (construction.cpp : 111) Max read length 100
0:00:00.103 8M / 12M INFO General (construction.cpp : 117) Average read length 99.9908
0:00:00.103 8M / 12M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting
0:00:00.105 8M / 12M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 400 files using 20 threads. This might take a while.
0:00:00.107 8M / 12M INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:00.107 8M / 12M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0665 Gb
0:00:00.107 8M / 12M INFO General (kmer_splitters.hpp : 97) Using cell size of 55924
0:00:13.677 11G / 11G INFO General (kmer_splitters.hpp : 289) Processed 28335304 reads
0:00:13.677 11G / 11G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K
0:00:43.443 84M / 11G INFO General (kmer_splitters.hpp : 308) Used 28335304 reads
0:00:43.443 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:00:47.300 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48221565 kmers in total.
0:00:47.300 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:00:53.614 84M / 11G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction
0:00:53.616 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:00:53.616 84M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:00:53.619 84M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:00:53.619 84M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0653 Gb
0:00:53.619 84M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:01:04.945 11G / 11G INFO General (kmer_splitters.hpp : 380) Processed 48221565 kmers
0:01:04.945 11G / 11G INFO General (kmer_splitters.hpp : 385) Used 48221565 kmers.
0:01:06.424 84M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:09.433 84M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48283647 kmers in total.
0:01:09.433 84M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:01:15.204 84M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:16.966 88M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:01:21.703 88M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22397344 bytes occupied (3.71096 bits per kmer).
0:01:21.745 136M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers
0:01:23.832 136M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished.
0:01:23.835 132M / 11G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph
0:01:23.899 136M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths
0:01:26.619 236M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 1195655 sequences extracted
0:01:27.985 236M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops
0:01:28.564 236M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 0 loops collected
0:01:29.162 508M / 11G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM)
0:01:29.162 508M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:29.162 508M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:01:30.371 564M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22370576 bytes occupied (3.7113 bits per kmer).
0:01:30.463 748M / 11G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while.
0:01:37.576 748M / 11G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM
0:01:39.436 748M / 11G INFO General (construction.cpp : 464) Processed 2391310 edges
0:01:39.710 444M / 11G INFO StageManager (stage.cpp : 132) STAGE == EC Threshold Finding
0:01:39.710 444M / 11G INFO General (kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:01:39.710 444M / 11G INFO General (kmer_coverage_model.cpp : 201) K-mer histogram maximum: 6
0:01:39.710 444M / 11G INFO General (kmer_coverage_model.cpp : 237) Estimated median coverage: 7. Coverage mad: 4.4478
0:01:39.710 444M / 11G INFO General (kmer_coverage_model.cpp : 259) Fitting coverage model
0:01:39.731 444M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 2
0:01:39.778 444M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 4
0:01:39.908 444M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 8
0:01:40.177 444M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 16
0:01:40.677 440M / 11G INFO General (kmer_coverage_model.cpp : 295) ... iteration 32
0:01:41.005 440M / 11G INFO General (kmer_coverage_model.cpp : 309) Fitted mean coverage: 7.50574. Fitted coverage std. dev: 2.88247
0:01:41.006 440M / 11G INFO General (kmer_coverage_model.cpp : 334) Probability of erroneous kmer at valley: 0.98299
0:01:41.006 440M / 11G INFO General (kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 5
0:01:41.006 440M / 11G INFO General (kmer_coverage_model.cpp : 362) Threshold adjusted to: 3
0:01:41.006 440M / 11G INFO General (kmer_coverage_model.cpp : 375) Estimated genome size (ignoring repeats): 35141486
0:01:41.006 440M / 11G INFO General (genomic_info_filler.cpp : 112) Mean coverage was calculated as 7.50574
0:01:41.006 440M / 11G INFO General (genomic_info_filler.cpp : 127) EC coverage threshold value was calculated as 3
0:01:41.006 440M / 11G INFO General (genomic_info_filler.cpp : 128) Trusted kmer low bound: 0
0:01:41.006 440M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:01:41.006 440M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:01:41.010 440M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:01:41.010 440M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:01:41.012 440M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:01:41.012 440M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0595 Gb
0:01:41.012 440M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:01:50.993 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 2391310 edges
0:01:50.993 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 2391310 sequences.
0:01:51.755 440M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:01:54.612 440M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 48221565 kmers in total.
0:01:54.612 440M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:02:00.421 440M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:02:02.364 456M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:02:07.837 456M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 22368640 bytes occupied (3.71098 bits per kmer).
0:02:08.414 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:02:09.628 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:02:09.640 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:02:11.599 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:02:14.386 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:02:14.386 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:02:14.811 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:02:18.417 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 132 gaps after checking 1631 candidates
0:02:18.519 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification
0:02:18.530 444M / 11G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning
0:02:18.530 444M / 11G INFO General (simplification.cpp : 68) Most init cleaning disabled since detected mean 7.50574 was less than activation coverage 10
0:02:18.530 444M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover
0:02:18.637 444M / 11G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times
0:02:18.637 444M / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification
0:02:18.637 444M / 11G INFO General (simplification.cpp : 357) Graph simplification started
0:02:18.637 444M / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:02:18.637 444M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1
0:02:18.637 444M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:24.477 468M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 294886 times
0:02:24.477 468M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:44.002 812M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 25800 times
0:02:44.002 812M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:45.506 808M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 29191 times
0:02:45.506 808M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2
0:02:45.506 808M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:45.610 808M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 292 times
0:02:45.610 808M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:48.712 864M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 2851 times
0:02:48.712 864M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:48.759 864M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1093 times
0:02:48.759 864M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3
0:02:48.759 864M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:48.783 864M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 20 times
0:02:48.783 864M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:49.116 868M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 181 times
0:02:49.116 868M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:49.141 868M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 582 times
0:02:49.141 868M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4
0:02:49.141 868M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:49.143 868M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 14 times
0:02:49.143 868M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:49.311 872M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 97 times
0:02:49.311 872M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:49.501 872M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 4998 times
0:02:49.501 872M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5
0:02:49.501 872M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:49.523 872M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 711 times
0:02:49.523 872M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:51.003 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1130 times
0:02:51.003 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:51.022 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 466 times
0:02:51.022 888M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6
0:02:51.022 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:51.033 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 46 times
0:02:51.033 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:51.146 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 69 times
0:02:51.146 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:51.160 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 368 times
0:02:51.160 888M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 7
0:02:51.160 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:51.161 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 26 times
0:02:51.161 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:51.262 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 63 times
0:02:51.263 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:51.290 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 748 times
0:02:51.290 888M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 8
0:02:51.290 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:51.292 888M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 46 times
0:02:51.292 888M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:51.444 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 99 times
0:02:51.445 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:51.463 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 483 times
0:02:51.463 892M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 9
0:02:51.463 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:51.464 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 8 times
0:02:51.464 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:51.535 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 43 times
0:02:51.535 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:51.557 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 594 times
0:02:51.557 892M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 10
0:02:51.557 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:51.558 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 17 times
0:02:51.558 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:51.639 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 51 times
0:02:51.639 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:51.683 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1158 times
0:02:51.683 892M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 11
0:02:51.683 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:51.771 892M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 122 times
0:02:51.771 892M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:52.378 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 134 times
0:02:52.378 896M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:52.451 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 1 times
0:02:52.451 896M / 11G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 12
0:02:52.451 896M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:02:52.452 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:02:52.452 896M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:02:52.452 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:02:52.452 896M / 11G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover
0:02:52.452 896M / 11G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times
0:02:52.452 896M / 11G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer
0:02:52.452 896M / 11G INFO General (graph_pack.hpp : 101) Index refill
0:02:52.458 896M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index
0:02:52.458 896M / 11G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 320 files using 20 threads. This might take a while.
0:02:52.460 896M / 11G INFO General (file_limit.hpp : 32) Open file limit set to 16384
0:02:52.460 896M / 11G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 17.0521 Gb
0:02:52.460 896M / 11G INFO General (kmer_splitters.hpp : 97) Using cell size of 69905
0:03:04.809 11G / 11G INFO General (edge_index_builders.hpp : 77) Processed 829992 edges
0:03:04.809 11G / 11G INFO General (edge_index_builders.hpp : 82) Used 829992 sequences.
0:03:05.541 896M / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting.
0:03:08.525 896M / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 40426065 kmers in total.
0:03:08.525 896M / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets.
0:03:13.511 896M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices
0:03:14.823 904M / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets.
0:03:18.856 904M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 18753840 bytes occupied (3.71124 bits per kmer).
0:03:19.551 1G / 11G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while.
0:03:20.485 1G / 11G INFO General (edge_index.hpp : 92) Index refilled
0:03:20.494 1G / 11G INFO General (gap_closer.cpp : 159) Preparing shift maps
0:03:21.449 1G / 11G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
0:03:25.398 1G / 11G INFO General (gap_closer.cpp : 138) Used 7016856 paired reads
0:03:25.398 1G / 11G INFO General (gap_closer.cpp : 140) Merging paired indices
0:03:25.612 1G / 11G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps
0:03:26.732 1G / 11G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 2 gaps after checking 548 candidates
0:03:26.785 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup
0:03:26.785 1G / 11G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification
0:03:26.785 1G / 11G INFO General (graph_simplification.hpp : 453) Disconnection of relatively low covered edges disabled
0:03:26.785 1G / 11G INFO General (graph_simplification.hpp : 489) Complex tip clipping disabled
0:03:26.786 1G / 11G INFO General (graph_simplification.hpp : 634) Creating parallel br instance
0:03:26.786 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:26.848 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:26.848 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:27.337 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:27.337 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper
0:03:27.404 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times
0:03:27.404 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover
0:03:27.892 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times
0:03:27.892 1G / 11G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges
0:03:28.603 1G / 11G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges
0:03:34.261 1G / 11G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 204386 times
0:03:34.261 1G / 11G INFO General (simplification.cpp : 470) Counting average coverage
0:03:34.429 1G / 11G INFO General (simplification.cpp : 476) Average coverage = 8.89253
0:03:34.429 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Mismatch Correction
0:03:34.429 1G / 11G INFO General (graph_pack.hpp : 109) Normalizing k-mer map. Total 6201874 kmers to process
0:03:39.783 1G / 11G INFO General (graph_pack.hpp : 111) Normalizing done
0:04:22.885 4G / 11G INFO General (mismatch_shall_not_pass.hp: 189) Finished collecting potential mismatches positions
0:04:37.527 1G / 11G INFO General (mismatch_shall_not_pass.hp: 290) All edges processed
0:04:37.894 1G / 11G INFO General (mismatch_correction.cpp : 27) Corrected 178 nucleotides
0:04:37.894 1G / 11G INFO StageManager (stage.cpp : 132) STAGE == Hybrid Aligning
0:04:37.894 1G / 11G INFO HybridAligning (hybrid_aligning.cpp : 322) Hybrid library detected: #1
0:04:37.894 1G / 11G INFO General (hybrid_aligning.cpp : 288) Aligning long reads with bwa-mem based aligner
0:05:23.222 2G / 11G INFO General (hybrid_aligning.cpp : 268) Prepared batch 0 of 50000 reads.
0:10:14.956 2G / 11G INFO General (hybrid_aligning.cpp : 233) Read batch of size: 50000 processed; 48920 of them longer than 500; among long reads aligned: 45497; paths of more than one edge received: 17098
0:10:15.257 2G / 11G INFO General (hybrid_aligning.cpp : 273) Processed 50000 reads
0:10:22.021 2G / 11G INFO General (hybrid_aligning.cpp : 268) Prepared batch 1 of 50000 reads.
0:14:38.500 3G / 11G INFO General (hybrid_aligning.cpp : 233) Read batch of size: 50000 processed; 48983 of them longer than 500; among long reads aligned: 45864; paths of more than one edge received: 17322
0:14:38.934 3G / 11G INFO General (hybrid_aligning.cpp : 273) Processed 100000 reads
0:14:45.392 2G / 11G INFO General (hybrid_aligning.cpp : 268) Prepared batch 2 of 50000 reads.
0:18:46.305 3G / 11G INFO General (hybrid_aligning.cpp : 233) Read batch of size: 50000 processed; 49006 of them longer than 500; among long reads aligned: 46112; paths of more than one edge received: 16864
0:18:46.871 3G / 11G INFO General (hybrid_aligning.cpp : 273) Processed 150000 reads
0:18:53.820 3G / 11G INFO General (hybrid_aligning.cpp : 268) Prepared batch 3 of 50000 reads.
0:22:48.139 3G / 11G INFO General (hybrid_aligning.cpp : 233) Read batch of size: 50000 processed; 49052 of them longer than 500; among long reads aligned: 46588; paths of more than one edge received: 16060
0:22:48.748 3G / 11G INFO General (hybrid_aligning.cpp : 273) Processed 200000 reads
0:22:55.820 3G / 11G INFO General (hybrid_aligning.cpp : 268) Prepared batch 4 of 50000 reads.

== Error == system call for: "['/home/AAFC-AAC/fuf/SPAdes/bin/spades-core', '/isilon/saskatoon-rdc/users/fuf/seq/BL_genome/seq/noncon/ref/asmm/BL06.sm.fasta/K77/configs/config.info']" finished abnormally, err code: -11

In case you have troubles running SPAdes, you can write to spades.support@cab.spbu.ru
or report an issue on our GitHub repository github.com/ablab/spades
Please provide us with params.txt and spades.log files from the output directory.

sunnycqcn · 2019-07-30T18:52:28Z

I do not know why I can not load the attachments.
Thanks,
Fuyou

alienzj · 2019-07-30T23:32:12Z

@sunnycqcn
Hello, Just drag the spades.log on the desktop directly into the browser input box.
If spades.log is bigger than 8Mbp, you can share it use cloud storage service.

sunnycqcn · 2019-07-31T16:09:42Z

@alienzj,
Thanks,
I tried as you said. But it was not work. I think our server block do this. My computer is not private computer.
Fuyou

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Spades stoped with unknown errors! #342

Spades stoped with unknown errors! #342

sunnycqcn commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

asl commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

alienzj commented Jul 30, 2019 •

edited

sunnycqcn commented Jul 31, 2019

Spades stoped with unknown errors! #342

Spades stoped with unknown errors! #342

Comments

sunnycqcn commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

asl commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

sunnycqcn commented Jul 30, 2019

alienzj commented Jul 30, 2019 • edited

sunnycqcn commented Jul 31, 2019

alienzj commented Jul 30, 2019 •

edited