[Debian-med-packaging] Bug#1011968: spades: autopkgtest regression
Paul Gevers
elbrus at debian.org
Sat May 28 06:27:31 BST 2022
Source: spades
Version: 3.15.4+dfsg-2
Severity: serious
User: debian-ci at lists.debian.org
Usertags: regression
Dear maintainer(s),
With a recent upload of spades the autopkgtest of spades fails in
testing when that autopkgtest is run with the binary packages of spades
from unstable. It passes when run with only packages from testing. In
tabular form:
pass fail
spades from testing 3.15.4+dfsg-2
all others from testing from testing
I copied some of the output at the bottom of this report.
Currently this regression is blocking the migration to testing [1]. Can
you please investigate the situation and fix it?
More information about this bug and the reason for filing it can be found on
https://wiki.debian.org/ContinuousIntegration/RegressionEmailInformation
Paul
[1] https://qa.debian.org/excuses.php?package=spades
https://ci.debian.net/data/autopkgtest/testing/amd64/s/spades/22180185/log.gz
== Warning == No assembly mode was specified! If you intend to assemble
high-coverage multi-cell/isolate data, use '--isolate' option.
Command line: /usr/libexec/spades/spades.py --test
System information:
SPAdes version: 3.15.4
Python version: 3.10.4
OS: Linux-5.10.0-14-amd64-x86_64-with-glibc2.33
Output dir: /tmp/tmp.Kw3upbPyKH/spades_test
Mode: read error correction and assembling
Debug mode is turned OFF
Dataset parameters:
Standard mode
For multi-cell/isolate data we recommend to use '--isolate' option;
for single-cell MDA data use '--sc'; for metagenomic data use '--meta';
for RNA-Seq use '--rna'.
Reads:
Library number: 1, library type: paired-end
orientation: fr
left reads: ['/usr/share/spades/test_dataset/ecoli_1K_1.fq.gz']
right reads: ['/usr/share/spades/test_dataset/ecoli_1K_2.fq.gz']
interlaced reads: not specified
single reads: not specified
merged reads: not specified
Read error correction parameters:
Iterations: 1
PHRED offset will be auto-detected
Corrected reads will be compressed
Assembly parameters:
k: automatic selection based on read length
Repeat resolution is enabled
Mismatch careful mode is turned OFF
MismatchCorrector will be SKIPPED
Coverage cutoff is turned OFF
Other parameters:
Dir for temp files: /tmp/tmp.Kw3upbPyKH/spades_test/tmp
Threads: 16
Memory limit (in Gb): 250
======= SPAdes pipeline started. Log can be found here:
/tmp/tmp.Kw3upbPyKH/spades_test/spades.log
/usr/share/spades/test_dataset/ecoli_1K_1.fq.gz: max reads length: 100
/usr/share/spades/test_dataset/ecoli_1K_2.fq.gz: max reads length: 100
Reads length: 100
===== Before start started.
===== Read error correction started.
===== Read error correction started.
== Running: /usr/libexec/spades/spades-hammer
/tmp/tmp.Kw3upbPyKH/spades_test/corrected/configs/config.info
0:00:00.000 1M / 16M INFO General (main.cpp
: 75) Starting BayesHammer, built from N/A, git
revision N/A
0:00:00.034 1M / 16M INFO General (main.cpp
: 76) Loading config from
/tmp/tmp.Kw3upbPyKH/spades_test/corrected/configs/config.info
0:00:00.066 1M / 16M INFO General (main.cpp
: 78) Maximum # of threads to use (adjusted due to
OMP capabilities): 16
0:00:00.082 1M / 16M INFO General
(memory_limit.cpp : 54) Memory limit set to 250 Gb
0:00:00.082 1M / 16M INFO General (main.cpp
: 86) Trying to determine PHRED offset
0:00:00.083 1M / 16M INFO General (main.cpp
: 92) Determined value is 33
0:00:00.083 1M / 16M INFO General
(hammer_tools.cpp : 38) Hamming graph threshold tau=1, k=21,
subkmer positions = [ 0 10 ]
0:00:00.083 1M / 16M INFO General (main.cpp
: 113) Size of aux. kmer data 24 bytes
=== ITERATION 0 begins ===
0:00:00.083 1M / 16M INFO General
(kmer_index_builder.hpp : 243) Splitting kmer instances into 16
files using 16 threads. This might take a while.
0:00:00.083 1M / 16M INFO General
(file_limit.hpp : 42) Open file limit set to 1024
0:00:00.083 1M / 16M INFO General
(kmer_splitter.hpp : 93) Memory available for splitting
buffers: 5.20833 Gb
0:00:00.083 1M / 16M INFO General
(kmer_splitter.hpp : 101) Using cell size of 4194304
0:00:00.222 9217M / 9217M INFO K-mer Splitting
(kmer_data.cpp : 97) Processing
/usr/share/spades/test_dataset/ecoli_1K_1.fq.gz
0:00:00.238 9217M / 9217M INFO K-mer Splitting
(kmer_data.cpp : 97) Processing
/usr/share/spades/test_dataset/ecoli_1K_2.fq.gz
0:00:00.250 9217M / 9217M INFO K-mer Splitting
(kmer_data.cpp : 112) Total 4108 reads processed
0:00:00.250 1M / 568M INFO General
(kmer_index_builder.hpp : 249) Starting k-mer counting.
0:00:00.257 1M / 568M INFO General
(kmer_index_builder.hpp : 260) K-mer counting done. There are 1974
kmers in total.
0:00:00.257 1M / 568M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:00.259 1M / 568M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 1974 kmers, 13944
bytes occupied (56.5106 bits per kmer).
0:00:00.259 1M / 568M INFO K-mer Counting
(kmer_data.cpp : 354) Arranging kmers in hash map order
0:00:00.260 1M / 568M INFO General (main.cpp
: 148) Clustering Hamming graph.
0:00:00.262 1M / 568M INFO General (main.cpp
: 155) Extracting clusters:
0:00:00.262 1M / 568M INFO General
(concurrent_dsu.cpp : 18) Connecting to root
0:00:00.262 1M / 568M INFO General
(concurrent_dsu.cpp : 34) Calculating counts
0:00:00.262 1M / 568M INFO General
(concurrent_dsu.cpp : 63) Writing down entries
0:00:00.263 1M / 568M INFO General (main.cpp
: 167) Clustering done. Total clusters: 1960
0:00:00.263 1M / 568M INFO K-mer Counting
(kmer_data.cpp : 371) Collecting K-mer information, this
takes a while.
0:00:00.263 1M / 568M INFO K-mer Counting
(kmer_data.cpp : 377) Processing
/usr/share/spades/test_dataset/ecoli_1K_1.fq.gz
0:00:00.273 1M / 568M INFO K-mer Counting
(kmer_data.cpp : 377) Processing
/usr/share/spades/test_dataset/ecoli_1K_2.fq.gz
0:00:00.281 1M / 568M INFO K-mer Counting
(kmer_data.cpp : 384) Collection done, postprocessing.
0:00:00.282 1M / 568M INFO K-mer Counting
(kmer_data.cpp : 397) There are 1974 kmers in total. Among
them 0 (0%) are singletons.
0:00:00.282 1M / 568M INFO General (main.cpp
: 173) Subclustering Hamming graph
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 650) Subclustering done. Total 0 non-read
kmers were generated.
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 651) Subclustering statistics:
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 652) Total singleton hamming clusters:
1946. Among them 1946 (100%) are good
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 653) Total singleton subclusters: 8.
Among them 8 (100%) are good
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 654) Total non-singleton subcluster
centers: 10. Among them 10 (100%) are good
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 655) Average size of non-trivial
subcluster: 2.8 kmers
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 656) Average number of sub-clusters per
non-singleton cluster: 1.28571
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 657) Total solid k-mers: 1964
0:00:00.283 1M / 568M INFO Hamming Subclustering
(kmer_cluster.cpp : 658) Substitution probabilities:
[4,4]((0.875,0.125,0,0),(0,1,0,0),(0,0,1,0),(0,0,0.125,0.875))
0:00:00.283 1M / 568M INFO General (main.cpp
: 178) Finished clustering.
0:00:00.283 1M / 568M INFO General (main.cpp
: 197) Starting solid k-mers expansion in 16 threads.
0:00:00.300 1M / 568M INFO General (main.cpp
: 218) Solid k-mers iteration 0 produced 0 new k-mers.
0:00:00.300 1M / 568M INFO General (main.cpp
: 222) Solid k-mers finalized
0:00:00.300 1M / 568M INFO General
(hammer_tools.cpp : 222) Starting read correction in 16 threads.
0:00:00.300 1M / 568M INFO General
(hammer_tools.cpp : 235) Correcting pair of reads:
/usr/share/spades/test_dataset/ecoli_1K_1.fq.gz and
/usr/share/spades/test_dataset/ecoli_1K_2.fq.gz
0:00:00.435 347M / 568M INFO General
(hammer_tools.cpp : 170) Prepared batch 0 of 2054 reads.
0:00:00.438 347M / 568M INFO General
(hammer_tools.cpp : 177) Processed batch 0
0:00:00.442 347M / 568M INFO General
(hammer_tools.cpp : 187) Written batch 0
0:00:00.477 1M / 568M INFO General
(hammer_tools.cpp : 276) Correction done. Changed 4 bases in
4 reads.
0:00:00.477 1M / 568M INFO General
(hammer_tools.cpp : 277) Failed to correct 0 bases out of 353915.
0:00:00.477 1M / 568M INFO General (main.cpp
: 255) Saving corrected dataset description to
/tmp/tmp.Kw3upbPyKH/spades_test/corrected/corrected.yaml
0:00:00.477 1M / 568M INFO General (main.cpp
: 262) All done. Exiting.
===== Read error correction finished.
===== corrected reads compression started.
== Running: /usr/bin/python3
/usr/share/spades/spades_pipeline/scripts/compress_all.py --input_file
/tmp/tmp.Kw3upbPyKH/spades_test/corrected/corrected.yaml
--ext_python_modules_home /usr/share/spades --max_threads 16
--output_dir /tmp/tmp.Kw3upbPyKH/spades_test/corrected --gzip_output
== Compressing corrected reads (with gzip)
== Files to compress:
['/tmp/tmp.Kw3upbPyKH/spades_test/corrected/ecoli_1K_1.fq.00.0_0.cor.fastq',
'/tmp/tmp.Kw3upbPyKH/spades_test/corrected/ecoli_1K_2.fq.00.0_0.cor.fastq',
'/tmp/tmp.Kw3upbPyKH/spades_test/corrected/ecoli_1K__unpaired.00.0_0.cor.fastq']
== Files compression is finished
== Dataset yaml file is updated
===== corrected reads compression finished.
===== Read error correction finished.
===== Assembling started.
===== K21 started.
== Running: /usr/libexec/spades/spades-core
/tmp/tmp.Kw3upbPyKH/spades_test/K21/configs/config.info
0:00:00.000 1M / 16M INFO General (main.cpp
: 99) Loaded config from
/tmp/tmp.Kw3upbPyKH/spades_test/K21/configs/config.info
0:00:00.000 1M / 16M INFO General
(memory_limit.cpp : 54) Memory limit set to 250 Gb
0:00:00.000 1M / 16M INFO General (main.cpp
: 107) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 1M / 16M INFO General (main.cpp
: 108) Maximum k-mer length: 128
0:00:00.000 1M / 16M INFO General (main.cpp
: 109) Assembling dataset
(/tmp/tmp.Kw3upbPyKH/spades_test/dataset.info) with K=21
0:00:00.001 1M / 16M INFO General (main.cpp
: 110) Maximum # of threads to use (adjusted due to
OMP capabilities): 16
0:00:00.001 1M / 16M INFO General
(pipeline.cpp : 212) SPAdes started
0:00:00.001 1M / 16M INFO General
(pipeline.cpp : 225) Starting from stage: read_conversion
0:00:00.001 1M / 16M INFO General
(pipeline.cpp : 231) Two-step repeat resolution disabled
0:00:00.001 1M / 16M INFO GraphCore
(graph_core.hpp : 672) Graph created, vertex min_id: 3,
edge min_id: 3
0:00:00.001 1M / 16M INFO GraphCore
(graph_core.hpp : 673) Vertex size: 48, edge size: 40
0:00:00.001 1M / 16M INFO General
(edge_index.hpp : 113) Size of edge index entries: 12/8
0:00:00.001 1M / 16M INFO StageManager (stage.cpp
: 185) STAGE == Binary Read Conversion (id:
read_conversion)
0:00:00.002 1M / 16M INFO General
(read_converter.cpp : 72) Converting reads to binary format
for library #0 (takes a while)
0:00:00.002 1M / 16M INFO General
(read_converter.cpp : 73) Converting paired reads
0:00:00.025 63M / 63M INFO General
(binary_converter.cpp : 111) 2054 reads written
0:00:00.025 41M / 41M INFO General
(read_converter.cpp : 86) Converting single reads
0:00:00.027 71M / 71M INFO General
(binary_converter.cpp : 111) 0 reads written
0:00:00.027 61M / 61M INFO General
(read_converter.cpp : 92) Converting merged reads
0:00:00.027 71M / 71M INFO General
(binary_converter.cpp : 111) 0 reads written
0:00:00.028 1M / 27M INFO StageManager (stage.cpp
: 185) STAGE == de Bruijn graph construction (id:
construction)
0:00:00.028 1M / 27M INFO General
(construction.cpp : 153) Max read length 100
0:00:00.029 1M / 27M INFO General
(construction.cpp : 159) Average read length 86.1526
0:00:00.029 1M / 27M INFO General (stage.cpp
: 117) PROCEDURE == k+1-mer counting (id:
construction:kpomer_counting)
0:00:00.029 1M / 27M INFO General
(kmer_index_builder.hpp : 243) Splitting kmer instances into 160
files using 16 threads. This might take a while.
0:00:00.029 1M / 27M INFO General
(file_limit.hpp : 42) Open file limit set to 1024
0:00:00.029 1M / 27M INFO General
(kmer_splitter.hpp : 93) Memory available for splitting
buffers: 5.20832 Gb
0:00:00.029 1M / 27M INFO General
(kmer_splitter.hpp : 101) Using cell size of 419430
0:00:01.488 1M / 5187M INFO General
(kmer_splitters.hpp : 131) Used 8216 reads
0:00:01.503 1M / 5187M INFO General
(kmer_index_builder.hpp : 249) Starting k-mer counting.
0:00:01.553 1M / 5187M INFO General
(kmer_index_builder.hpp : 260) K-mer counting done. There are 984
kmers in total.
0:00:01.553 1M / 5187M INFO General (stage.cpp
: 117) PROCEDURE == Extension index construction (id:
construction:extension_index_construction)
0:00:01.555 1M / 5187M INFO K-mer Index Building
(kmer_index_builder.hpp : 438) Building kmer index
0:00:01.555 1M / 5187M INFO General
(kmer_index_builder.hpp : 243) Splitting kmer instances into 160
files using 16 threads. This might take a while.
0:00:01.555 1M / 5187M INFO General
(file_limit.hpp : 42) Open file limit set to 1024
0:00:01.555 1M / 5187M INFO General
(kmer_splitter.hpp : 93) Memory available for splitting
buffers: 5.20832 Gb
0:00:01.555 1M / 5187M INFO General
(kmer_splitter.hpp : 101) Using cell size of 419430
0:00:02.928 9601M / 9601M INFO General
(kmer_splitters.hpp : 199) Used 984 kmers.
0:00:02.929 1M / 5187M INFO General
(kmer_index_builder.hpp : 249) Starting k-mer counting.
0:00:02.951 1M / 5187M INFO General
(kmer_index_builder.hpp : 260) K-mer counting done. There are 985
kmers in total.
0:00:02.951 1M / 5187M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:02.963 2M / 5187M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 985 kmers, 127200
bytes occupied (1033.1 bits per kmer).
0:00:02.963 2M / 5187M INFO General
(kmer_index_builder.hpp : 169) Merging final buckets.
0:00:02.969 2M / 5187M INFO DeBruijnExtensionIndexBu
(kmer_extension_index_build: 100) Building k-mer extensions from k+1-mers
0:00:02.971 2M / 5187M INFO DeBruijnExtensionIndexBu
(kmer_extension_index_build: 105) Building k-mer extensions from
k+1-mers finished.
0:00:02.973 1M / 5187M INFO General (stage.cpp
: 117) PROCEDURE == Early tip clipping (id:
construction:early_tip_clipper)
0:00:02.973 1M / 5187M INFO General
(construction.cpp : 301) Early tip clipper length bound set
as (RL - K)
0:00:02.973 1M / 5187M INFO Early tip clipping
(early_simplification.hpp : 47) Early tip clipping
0:00:02.974 1M / 5187M INFO Early tip clipping
(early_simplification.hpp : 82) #tipped junctions: 2
0:00:02.974 1M / 5187M INFO Early tip clipping
(early_simplification.hpp : 93) Clipped tips: 2
0:00:02.974 1M / 5187M INFO Early tip clipping
(early_simplification.hpp : 49) 5 22-mers were removed by early tip
clipper
0:00:02.974 1M / 5187M INFO General (stage.cpp
: 117) PROCEDURE == Condensing graph (id:
construction:graph_condensing)
0:00:02.974 1M / 5187M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 354) Extracting unbranching paths
0:00:02.974 1M / 5187M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 373) Extracting unbranching paths
finished. 1 sequences extracted
0:00:02.974 1M / 5187M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 309) Collecting perfect loops
0:00:02.974 1M / 5187M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 342) Collecting perfect loops finished. 0
loops collected
0:00:02.974 1M / 5187M INFO General
(debruijn_graph_constructor: 487) Total 2 edges to create
0:00:02.974 1M / 5187M INFO General
(debruijn_graph_constructor: 489) Collecting link records
0:00:02.975 1M / 5187M INFO General
(debruijn_graph_constructor: 491) Ordering link records
0:00:02.975 1M / 5187M INFO General
(debruijn_graph_constructor: 493) Sorting done
0:00:02.975 1M / 5187M INFO General
(debruijn_graph_constructor: 503) Total 2 vertices to create
0:00:02.975 1M / 5187M INFO General
(debruijn_graph_constructor: 506) Connecting the graph
0:00:02.975 1M / 5187M INFO General (stage.cpp
: 117) PROCEDURE == Filling coverage indices (PHM)
(id: construction:coverage_filling_phm)
0:00:02.975 2M / 5187M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:02.987 2M / 5187M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 984 kmers, 128008
bytes occupied (1040.72 bits per kmer).
0:00:02.987 2M / 5187M INFO General
(coverage_hash_map_builder.: 47) Collecting k-mer coverage
information from reads, this takes a while.
0:00:02.994 2M / 5187M INFO General
(construction.cpp : 430) Filling coverage and flanking
coverage from PHM
0:00:02.998 1M / 5187M INFO StageManager (stage.cpp
: 185) STAGE == EC Threshold Finding (id:
ec_threshold_finder)
0:00:02.999 1M / 5187M INFO General
(kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:00:02.999 1M / 5187M INFO General
(kmer_coverage_model.cpp : 201) K-mer histogram maximum: 348
0:00:02.999 1M / 5187M INFO General
(kmer_coverage_model.cpp : 237) Estimated median coverage: 348.
Coverage mad: 62.2692
0:00:02.999 1M / 5187M INFO General
(kmer_coverage_model.cpp : 259) Fitting coverage model
0:00:03.048 1M / 5187M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 2
0:00:03.147 1M / 5187M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 4
0:00:03.346 1M / 5187M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 8
0:00:03.639 1M / 5187M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 16
0:00:04.157 1M / 5187M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 32
0:00:05.406 1M / 5187M INFO General
(kmer_coverage_model.cpp : 309) Fitted mean coverage: 342.845.
Fitted coverage std. dev: 68.3997
0:00:05.407 1M / 5187M INFO General
(kmer_coverage_model.cpp : 334) Probability of erroneous kmer at
valley: 0.999994
0:00:05.407 1M / 5187M INFO General
(kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 355
0:00:05.407 1M / 5187M INFO General
(kmer_coverage_model.cpp : 362) Threshold adjusted to: 171
0:00:05.407 1M / 5187M INFO General
(kmer_coverage_model.cpp : 375) Estimated genome size (ignoring
repeats): 749
0:00:05.407 1M / 5187M INFO General
(genomic_info_filler.cpp : 55) Mean coverage was calculated as 342.845
0:00:05.407 1M / 5187M INFO General
(genomic_info_filler.cpp : 70) EC coverage threshold value was
calculated as 171
0:00:05.407 1M / 5187M INFO General
(genomic_info_filler.cpp : 71) Trusted kmer low bound: 0
0:00:05.407 1M / 5187M INFO StageManager (stage.cpp
: 185) STAGE == Raw Simplification (id:
raw_simplification)
0:00:05.407 1M / 5187M INFO General
(simplification.cpp : 127) PROCEDURE == Initial cleaning
0:00:05.407 1M / 5187M INFO General
(graph_simplification.hpp : 662) Flanking coverage based
disconnection disabled
0:00:05.407 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Self conjugate edge remover
0:00:05.407 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Self conjugate edge remover
triggered 0 times
0:00:05.407 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Initial tip clipper
0:00:05.407 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Initial tip clipper triggered 0 times
0:00:05.407 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Initial ec remover
0:00:05.407 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Initial ec remover triggered 0 times
0:00:05.407 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Initial isolated edge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Initial isolated edge remover
triggered 0 times
0:00:05.408 1M / 5187M INFO StageManager (stage.cpp
: 185) STAGE == Simplification (id: simplification)
0:00:05.408 1M / 5187M INFO General
(simplification.cpp : 368) Graph simplification started
0:00:05.408 1M / 5187M INFO General
(graph_simplification.hpp : 634) Creating parallel br instance
0:00:05.408 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 1
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.408 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 2
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.408 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 3
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.408 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 4
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.408 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 5
0:00:05.408 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.409 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 6
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.409 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 7
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.409 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 8
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.409 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 9
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.409 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 10
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.409 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 11
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.410 1M / 5187M INFO StageManager (stage.cpp
: 185) STAGE == Simplification Cleanup (id:
simplification_cleanup)
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 176) PROCEDURE == Post simplification
0:00:05.410 1M / 5187M INFO General
(graph_simplification.hpp : 448) Disconnection of relatively low
covered edges disabled
0:00:05.410 1M / 5187M INFO General
(graph_simplification.hpp : 485) Complex tip clipping disabled
0:00:05.410 1M / 5187M INFO General
(graph_simplification.hpp : 634) Creating parallel br instance
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 327) Disrupting self-conjugate edges
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 167) Running Removing isolated edges
0:00:05.410 1M / 5187M INFO Simplification
(parallel_processing.hpp : 170) Removing isolated edges triggered 0
times
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 495) After simplification:
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 496) Average coverage = 273.35
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 497) Total length = 979
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 498) Median edge length: 979
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 499) Edges: 2
0:00:05.410 1M / 5187M INFO General
(simplification.cpp : 500) Vertices: 4
0:00:05.410 1M / 5187M INFO StageManager (stage.cpp
: 185) STAGE == Contig Output (id: contig_output)
0:00:05.411 1M / 5187M INFO General
(read_converter.cpp : 107) Outputting contigs to
/tmp/tmp.Kw3upbPyKH/spades_test/K21/simplified_contigs
0:00:05.411 3M / 5187M INFO General
(binary_converter.cpp : 111) 1 reads written
0:00:05.413 1M / 5187M INFO General
(pipeline.cpp : 287) SPAdes finished
0:00:05.413 1M / 5187M INFO General (main.cpp
: 136) Assembling time: 0 hours 0 minutes 5 seconds
===== K21 finished.
===== K33 started.
== Running: /usr/libexec/spades/spades-core
/tmp/tmp.Kw3upbPyKH/spades_test/K33/configs/config.info
0:00:00.000 1M / 16M INFO General (main.cpp
: 99) Loaded config from
/tmp/tmp.Kw3upbPyKH/spades_test/K33/configs/config.info
0:00:00.000 1M / 16M INFO General
(memory_limit.cpp : 54) Memory limit set to 250 Gb
0:00:00.000 1M / 16M INFO General (main.cpp
: 107) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 1M / 16M INFO General (main.cpp
: 108) Maximum k-mer length: 128
0:00:00.000 1M / 16M INFO General (main.cpp
: 109) Assembling dataset
(/tmp/tmp.Kw3upbPyKH/spades_test/dataset.info) with K=33
0:00:00.000 1M / 16M INFO General (main.cpp
: 110) Maximum # of threads to use (adjusted due to
OMP capabilities): 16
0:00:00.000 1M / 16M INFO General
(pipeline.cpp : 212) SPAdes started
0:00:00.000 1M / 16M INFO General
(pipeline.cpp : 225) Starting from stage: read_conversion
0:00:00.000 1M / 16M INFO General
(pipeline.cpp : 231) Two-step repeat resolution disabled
0:00:00.000 1M / 16M INFO GraphCore
(graph_core.hpp : 672) Graph created, vertex min_id: 3,
edge min_id: 3
0:00:00.000 1M / 16M INFO GraphCore
(graph_core.hpp : 673) Vertex size: 48, edge size: 40
0:00:00.000 1M / 16M INFO General
(edge_index.hpp : 113) Size of edge index entries: 12/8
0:00:00.001 1M / 16M INFO StageManager (stage.cpp
: 185) STAGE == Binary Read Conversion (id:
read_conversion)
0:00:00.001 1M / 16M INFO General
(read_converter.cpp : 53) Binary reads detected
0:00:00.002 1M / 16M INFO StageManager (stage.cpp
: 185) STAGE == de Bruijn graph construction (id:
construction)
0:00:00.002 1M / 16M INFO General
(construction.cpp : 118) Contigs from previous K will be
used: /tmp/tmp.Kw3upbPyKH/spades_test/K21/simplified_contigs
0:00:00.046 1M / 16M INFO General
(construction.cpp : 153) Max read length 100
0:00:00.047 1M / 16M INFO General
(construction.cpp : 159) Average read length 86.1526
0:00:00.047 1M / 16M INFO General (stage.cpp
: 117) PROCEDURE == k+1-mer counting (id:
construction:kpomer_counting)
0:00:00.047 1M / 16M INFO General
(kmer_index_builder.hpp : 243) Splitting kmer instances into 160
files using 16 threads. This might take a while.
0:00:00.047 1M / 16M INFO General
(file_limit.hpp : 42) Open file limit set to 1024
0:00:00.047 1M / 16M INFO General
(kmer_splitter.hpp : 93) Memory available for splitting
buffers: 5.20832 Gb
0:00:00.047 1M / 16M INFO General
(kmer_splitter.hpp : 101) Using cell size of 209715
0:00:01.540 1M / 5192M INFO General
(kmer_splitters.hpp : 131) Used 8218 reads
0:00:01.554 1M / 5192M INFO General
(kmer_index_builder.hpp : 249) Starting k-mer counting.
0:00:01.562 1M / 5192M INFO General
(kmer_index_builder.hpp : 260) K-mer counting done. There are 972
kmers in total.
0:00:01.562 1M / 5192M INFO General (stage.cpp
: 117) PROCEDURE == Extension index construction (id:
construction:extension_index_construction)
0:00:01.564 1M / 5192M INFO K-mer Index Building
(kmer_index_builder.hpp : 438) Building kmer index
0:00:01.564 1M / 5192M INFO General
(kmer_index_builder.hpp : 243) Splitting kmer instances into 160
files using 16 threads. This might take a while.
0:00:01.564 1M / 5192M INFO General
(file_limit.hpp : 42) Open file limit set to 1024
0:00:01.564 1M / 5192M INFO General
(kmer_splitter.hpp : 93) Memory available for splitting
buffers: 5.20832 Gb
0:00:01.564 1M / 5192M INFO General
(kmer_splitter.hpp : 101) Using cell size of 209715
0:00:02.935 9602M / 9602M INFO General
(kmer_splitters.hpp : 199) Used 972 kmers.
0:00:03.088 2M / 5192M INFO General
(kmer_index_builder.hpp : 249) Starting k-mer counting.
0:00:03.110 2M / 5192M INFO General
(kmer_index_builder.hpp : 260) K-mer counting done. There are 973
kmers in total.
0:00:03.110 2M / 5192M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:03.122 2M / 5192M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 973 kmers, 128000
bytes occupied (1052.42 bits per kmer).
0:00:03.122 2M / 5192M INFO General
(kmer_index_builder.hpp : 169) Merging final buckets.
0:00:03.128 2M / 5192M INFO DeBruijnExtensionIndexBu
(kmer_extension_index_build: 100) Building k-mer extensions from k+1-mers
0:00:03.131 2M / 5192M INFO DeBruijnExtensionIndexBu
(kmer_extension_index_build: 105) Building k-mer extensions from
k+1-mers finished.
0:00:03.133 2M / 5192M INFO General (stage.cpp
: 117) PROCEDURE == Early tip clipping (id:
construction:early_tip_clipper)
0:00:03.133 2M / 5192M INFO General
(construction.cpp : 301) Early tip clipper length bound set
as (RL - K)
0:00:03.133 2M / 5192M INFO Early tip clipping
(early_simplification.hpp : 47) Early tip clipping
0:00:03.133 2M / 5192M INFO Early tip clipping
(early_simplification.hpp : 82) #tipped junctions: 2
0:00:03.133 2M / 5192M INFO Early tip clipping
(early_simplification.hpp : 93) Clipped tips: 2
0:00:03.133 2M / 5192M INFO Early tip clipping
(early_simplification.hpp : 49) 5 34-mers were removed by early tip
clipper
0:00:03.133 2M / 5192M INFO General (stage.cpp
: 117) PROCEDURE == Condensing graph (id:
construction:graph_condensing)
0:00:03.133 2M / 5192M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 354) Extracting unbranching paths
0:00:03.134 2M / 5192M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 373) Extracting unbranching paths
finished. 1 sequences extracted
0:00:03.134 2M / 5192M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 309) Collecting perfect loops
0:00:03.134 2M / 5192M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 342) Collecting perfect loops finished. 0
loops collected
0:00:03.134 2M / 5192M INFO General
(debruijn_graph_constructor: 487) Total 2 edges to create
0:00:03.135 2M / 5192M INFO General
(debruijn_graph_constructor: 489) Collecting link records
0:00:03.135 2M / 5192M INFO General
(debruijn_graph_constructor: 491) Ordering link records
0:00:03.135 2M / 5192M INFO General
(debruijn_graph_constructor: 493) Sorting done
0:00:03.135 2M / 5192M INFO General
(debruijn_graph_constructor: 503) Total 2 vertices to create
0:00:03.136 2M / 5192M INFO General
(debruijn_graph_constructor: 506) Connecting the graph
0:00:03.136 2M / 5192M INFO General (stage.cpp
: 117) PROCEDURE == Filling coverage indices (PHM)
(id: construction:coverage_filling_phm)
0:00:03.136 2M / 5192M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:03.148 2M / 5192M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 972 kmers, 126400
bytes occupied (1040.33 bits per kmer).
0:00:03.148 2M / 5192M INFO General
(coverage_hash_map_builder.: 47) Collecting k-mer coverage
information from reads, this takes a while.
0:00:03.154 2M / 5192M INFO General
(construction.cpp : 430) Filling coverage and flanking
coverage from PHM
0:00:03.158 1M / 5192M INFO StageManager (stage.cpp
: 185) STAGE == EC Threshold Finding (id:
ec_threshold_finder)
0:00:03.158 1M / 5192M INFO General
(kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:00:03.160 1M / 5192M INFO General
(kmer_coverage_model.cpp : 201) K-mer histogram maximum: 17
0:00:03.160 1M / 5192M INFO General
(kmer_coverage_model.cpp : 237) Estimated median coverage: 17.
Coverage mad: 11.8608
0:00:03.160 1M / 5192M INFO General
(kmer_coverage_model.cpp : 259) Fitting coverage model
0:00:03.180 1M / 5192M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 2
0:00:03.228 1M / 5192M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 4
0:00:03.299 1M / 5192M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 8
0:00:03.398 1M / 5192M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 16
0:00:03.574 1M / 5192M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 32
0:00:03.906 1M / 5192M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 64
0:00:04.505 1M / 5192M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 128
0:00:05.326 1M / 5192M INFO General
(kmer_coverage_model.cpp : 309) Fitted mean coverage: 108.181.
Fitted coverage std. dev: 65.0594
0:00:05.327 1M / 5192M INFO General
(kmer_coverage_model.cpp : 334) Probability of erroneous kmer at
valley: 0.0555142
0:00:05.327 1M / 5192M INFO General
(kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 3
0:00:05.327 1M / 5192M INFO General
(kmer_coverage_model.cpp : 362) Threshold adjusted to: 3
0:00:05.327 1M / 5192M INFO General
(kmer_coverage_model.cpp : 375) Estimated genome size (ignoring
repeats): 400
0:00:05.327 1M / 5192M INFO General
(genomic_info_filler.cpp : 55) Mean coverage was calculated as 108.181
0:00:05.327 1M / 5192M INFO General
(genomic_info_filler.cpp : 70) EC coverage threshold value was
calculated as 3
0:00:05.327 1M / 5192M INFO General
(genomic_info_filler.cpp : 71) Trusted kmer low bound: 0
0:00:05.327 1M / 5192M INFO StageManager (stage.cpp
: 185) STAGE == Raw Simplification (id:
raw_simplification)
0:00:05.327 1M / 5192M INFO General
(simplification.cpp : 127) PROCEDURE == Initial cleaning
0:00:05.327 1M / 5192M INFO General
(graph_simplification.hpp : 662) Flanking coverage based
disconnection disabled
0:00:05.327 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Self conjugate edge remover
0:00:05.327 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Self conjugate edge remover
triggered 0 times
0:00:05.327 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Initial tip clipper
0:00:05.327 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Initial tip clipper triggered 0 times
0:00:05.327 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Initial ec remover
0:00:05.327 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Initial ec remover triggered 0 times
0:00:05.327 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Initial isolated edge remover
0:00:05.327 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Initial isolated edge remover
triggered 0 times
0:00:05.327 1M / 5192M INFO StageManager (stage.cpp
: 185) STAGE == Simplification (id: simplification)
0:00:05.327 1M / 5192M INFO General
(simplification.cpp : 368) Graph simplification started
0:00:05.328 1M / 5192M INFO General
(graph_simplification.hpp : 634) Creating parallel br instance
0:00:05.328 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 1
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.328 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 2
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.328 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 3
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.328 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 4
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.328 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 5
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.328 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 6
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.328 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.329 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 7
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.329 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 8
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.329 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 9
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.329 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 10
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.329 1M / 5192M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 11
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:05.329 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:05.329 1M / 5192M INFO StageManager (stage.cpp
: 185) STAGE == Simplification Cleanup (id:
simplification_cleanup)
0:00:05.330 1M / 5192M INFO General
(simplification.cpp : 176) PROCEDURE == Post simplification
0:00:05.330 1M / 5192M INFO General
(graph_simplification.hpp : 448) Disconnection of relatively low
covered edges disabled
0:00:05.330 1M / 5192M INFO General
(graph_simplification.hpp : 485) Complex tip clipping disabled
0:00:05.330 1M / 5192M INFO General
(graph_simplification.hpp : 634) Creating parallel br instance
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:05.330 1M / 5192M INFO General
(simplification.cpp : 327) Disrupting self-conjugate edges
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 167) Running Removing isolated edges
0:00:05.330 1M / 5192M INFO Simplification
(parallel_processing.hpp : 170) Removing isolated edges triggered 0
times
0:00:05.330 1M / 5192M INFO General
(simplification.cpp : 495) After simplification:
0:00:05.330 1M / 5192M INFO General
(simplification.cpp : 496) Average coverage = 225.839
0:00:05.330 1M / 5192M INFO General
(simplification.cpp : 497) Total length = 967
0:00:05.330 1M / 5192M INFO General
(simplification.cpp : 498) Median edge length: 967
0:00:05.330 1M / 5192M INFO General
(simplification.cpp : 499) Edges: 2
0:00:05.330 1M / 5192M INFO General
(simplification.cpp : 500) Vertices: 4
0:00:05.330 1M / 5192M INFO StageManager (stage.cpp
: 185) STAGE == Contig Output (id: contig_output)
0:00:05.330 1M / 5192M INFO General
(read_converter.cpp : 107) Outputting contigs to
/tmp/tmp.Kw3upbPyKH/spades_test/K33/simplified_contigs
0:00:05.331 3M / 5192M INFO General
(binary_converter.cpp : 111) 1 reads written
0:00:05.332 1M / 5192M INFO General
(pipeline.cpp : 287) SPAdes finished
0:00:05.332 1M / 5192M INFO General (main.cpp
: 136) Assembling time: 0 hours 0 minutes 5 seconds
===== K33 finished.
===== K55 started.
== Running: /usr/libexec/spades/spades-core
/tmp/tmp.Kw3upbPyKH/spades_test/K55/configs/config.info
0:00:00.000 1M / 16M INFO General (main.cpp
: 99) Loaded config from
/tmp/tmp.Kw3upbPyKH/spades_test/K55/configs/config.info
0:00:00.000 1M / 16M INFO General
(memory_limit.cpp : 54) Memory limit set to 250 Gb
0:00:00.000 1M / 16M INFO General (main.cpp
: 107) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 1M / 16M INFO General (main.cpp
: 108) Maximum k-mer length: 128
0:00:00.000 1M / 16M INFO General (main.cpp
: 109) Assembling dataset
(/tmp/tmp.Kw3upbPyKH/spades_test/dataset.info) with K=55
0:00:00.000 1M / 16M INFO General (main.cpp
: 110) Maximum # of threads to use (adjusted due to
OMP capabilities): 16
0:00:00.000 1M / 16M INFO General
(pipeline.cpp : 212) SPAdes started
0:00:00.000 1M / 16M INFO General
(pipeline.cpp : 225) Starting from stage: read_conversion
0:00:00.000 1M / 16M INFO General
(pipeline.cpp : 231) Two-step repeat resolution disabled
0:00:00.000 1M / 16M INFO GraphCore
(graph_core.hpp : 672) Graph created, vertex min_id: 3,
edge min_id: 3
0:00:00.000 1M / 16M INFO GraphCore
(graph_core.hpp : 673) Vertex size: 48, edge size: 40
0:00:00.000 1M / 16M INFO General
(edge_index.hpp : 113) Size of edge index entries: 12/8
0:00:00.000 1M / 16M INFO General
(pipeline.cpp : 242) Will need read mapping, kmer mapper
will be attached
0:00:00.001 1M / 16M INFO StageManager (stage.cpp
: 185) STAGE == Binary Read Conversion (id:
read_conversion)
0:00:00.001 1M / 16M INFO General
(read_converter.cpp : 53) Binary reads detected
0:00:00.002 1M / 16M INFO StageManager (stage.cpp
: 185) STAGE == de Bruijn graph construction (id:
construction)
0:00:00.002 1M / 16M INFO General
(construction.cpp : 118) Contigs from previous K will be
used: /tmp/tmp.Kw3upbPyKH/spades_test/K33/simplified_contigs
0:00:00.045 1M / 16M INFO General
(construction.cpp : 153) Max read length 100
0:00:00.045 1M / 16M INFO General
(construction.cpp : 159) Average read length 86.1526
0:00:00.045 1M / 16M INFO General (stage.cpp
: 117) PROCEDURE == k+1-mer counting (id:
construction:kpomer_counting)
0:00:00.045 1M / 16M INFO General
(kmer_index_builder.hpp : 243) Splitting kmer instances into 160
files using 16 threads. This might take a while.
0:00:00.045 1M / 16M INFO General
(file_limit.hpp : 42) Open file limit set to 1024
0:00:00.045 1M / 16M INFO General
(kmer_splitter.hpp : 93) Memory available for splitting
buffers: 5.20832 Gb
0:00:00.045 1M / 16M INFO General
(kmer_splitter.hpp : 101) Using cell size of 209715
0:00:01.488 1M / 5186M INFO General
(kmer_splitters.hpp : 131) Used 8218 reads
0:00:01.503 1M / 5186M INFO General
(kmer_index_builder.hpp : 249) Starting k-mer counting.
0:00:01.514 1M / 5186M INFO General
(kmer_index_builder.hpp : 260) K-mer counting done. There are 949
kmers in total.
0:00:01.514 1M / 5186M INFO General (stage.cpp
: 117) PROCEDURE == Extension index construction (id:
construction:extension_index_construction)
0:00:01.516 1M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 438) Building kmer index
0:00:01.516 1M / 5186M INFO General
(kmer_index_builder.hpp : 243) Splitting kmer instances into 160
files using 16 threads. This might take a while.
0:00:01.516 1M / 5186M INFO General
(file_limit.hpp : 42) Open file limit set to 1024
0:00:01.516 1M / 5186M INFO General
(kmer_splitter.hpp : 93) Memory available for splitting
buffers: 5.20832 Gb
0:00:01.516 1M / 5186M INFO General
(kmer_splitter.hpp : 101) Using cell size of 209715
0:00:02.862 9602M / 9602M INFO General
(kmer_splitters.hpp : 199) Used 949 kmers.
0:00:02.863 2M / 5186M INFO General
(kmer_index_builder.hpp : 249) Starting k-mer counting.
0:00:02.888 2M / 5186M INFO General
(kmer_index_builder.hpp : 260) K-mer counting done. There are 951
kmers in total.
0:00:02.888 2M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:02.901 2M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 951 kmers, 126400
bytes occupied (1063.3 bits per kmer).
0:00:02.902 2M / 5186M INFO General
(kmer_index_builder.hpp : 169) Merging final buckets.
0:00:02.908 2M / 5186M INFO DeBruijnExtensionIndexBu
(kmer_extension_index_build: 100) Building k-mer extensions from k+1-mers
0:00:02.910 2M / 5186M INFO DeBruijnExtensionIndexBu
(kmer_extension_index_build: 105) Building k-mer extensions from
k+1-mers finished.
0:00:02.912 2M / 5186M INFO General (stage.cpp
: 117) PROCEDURE == Condensing graph (id:
construction:graph_condensing)
0:00:02.913 2M / 5186M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 354) Extracting unbranching paths
0:00:02.913 2M / 5186M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 373) Extracting unbranching paths
finished. 4 sequences extracted
0:00:02.913 2M / 5186M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 309) Collecting perfect loops
0:00:02.913 2M / 5186M INFO UnbranchingPathExtractor
(debruijn_graph_constructor: 342) Collecting perfect loops finished. 0
loops collected
0:00:02.913 2M / 5186M INFO General
(debruijn_graph_constructor: 487) Total 8 edges to create
0:00:02.913 2M / 5186M INFO General
(debruijn_graph_constructor: 489) Collecting link records
0:00:02.913 2M / 5186M INFO General
(debruijn_graph_constructor: 491) Ordering link records
0:00:02.913 2M / 5186M INFO General
(debruijn_graph_constructor: 493) Sorting done
0:00:02.913 2M / 5186M INFO General
(debruijn_graph_constructor: 503) Total 6 vertices to create
0:00:02.913 2M / 5186M INFO General
(debruijn_graph_constructor: 506) Connecting the graph
0:00:02.913 2M / 5186M INFO General (stage.cpp
: 117) PROCEDURE == Filling coverage indices (PHM)
(id: construction:coverage_filling_phm)
0:00:02.914 2M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:02.925 2M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 949 kmers, 128000
bytes occupied (1079.03 bits per kmer).
0:00:02.925 2M / 5186M INFO General
(coverage_hash_map_builder.: 47) Collecting k-mer coverage
information from reads, this takes a while.
0:00:02.929 2M / 5186M INFO General
(construction.cpp : 430) Filling coverage and flanking
coverage from PHM
0:00:02.933 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == EC Threshold Finding (id:
ec_threshold_finder)
0:00:02.933 1M / 5186M INFO General
(kmer_coverage_model.cpp : 181) Kmer coverage valley at: 0
0:00:02.934 1M / 5186M INFO General
(kmer_coverage_model.cpp : 201) K-mer histogram maximum: 6
0:00:02.934 1M / 5186M INFO General
(kmer_coverage_model.cpp : 237) Estimated median coverage: 6.
Coverage mad: 4.4478
0:00:02.934 1M / 5186M INFO General
(kmer_coverage_model.cpp : 259) Fitting coverage model
0:00:02.939 1M / 5186M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 2
0:00:02.959 1M / 5186M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 4
0:00:03.016 1M / 5186M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 8
0:00:03.098 1M / 5186M INFO General
(kmer_coverage_model.cpp : 295) ... iteration 16
0:00:03.171 1M / 5186M INFO General
(kmer_coverage_model.cpp : 309) Fitted mean coverage: 13.7375.
Fitted coverage std. dev: 9.60863
0:00:03.171 1M / 5186M INFO General
(kmer_coverage_model.cpp : 334) Probability of erroneous kmer at
valley: 2.02732e-07
0:00:03.171 1M / 5186M INFO General
(kmer_coverage_model.cpp : 358) Preliminary threshold calculated as: 1
0:00:03.171 1M / 5186M INFO General
(kmer_coverage_model.cpp : 362) Threshold adjusted to: 1
0:00:03.171 1M / 5186M INFO General
(kmer_coverage_model.cpp : 375) Estimated genome size (ignoring
repeats): 238
0:00:03.171 1M / 5186M INFO General
(genomic_info_filler.cpp : 55) Mean coverage was calculated as 13.7375
0:00:03.171 1M / 5186M INFO General
(genomic_info_filler.cpp : 70) EC coverage threshold value was
calculated as 1
0:00:03.171 1M / 5186M INFO General
(genomic_info_filler.cpp : 71) Trusted kmer low bound: 0
0:00:03.171 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Gap Closer (id: early_gapcloser)
0:00:03.177 10M / 5186M INFO General
(edge_index.hpp : 113) Size of edge index entries: 12/8
0:00:03.177 10M / 5186M INFO General
(gap_closer.cpp : 101) Total edges in tip neighborhood: 7
out of 8, length: 1520
0:00:03.177 10M / 5186M INFO General
(edge_index.hpp : 167) Using small index (max_id = 11)
0:00:03.178 10M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:03.179 10M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 949 kmers, 1456
bytes occupied (12.274 bits per kmer).
0:00:03.179 10M / 5186M INFO General
(edge_index_builders.hpp : 265) Collecting edge information from
graph, this takes a while.
0:00:03.181 10M / 5186M INFO General
(sequence_mapper_notifier.h: 95) Total 2054 reads processed
0:00:03.184 10M / 5186M INFO General
(gap_closer.cpp : 452) Initializing gap closer
0:00:03.184 10M / 5186M INFO GapCloser
(gap_closer.cpp : 359) Closing short gaps
0:00:03.185 10M / 5186M INFO GapCloser
(gap_closer.cpp : 391) Closing short gaps complete: filled
0 gaps after checking 4 candidates
0:00:03.185 10M / 5186M INFO General
(gap_closer.cpp : 456) Gap closer done
0:00:03.185 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Raw Simplification (id:
raw_simplification)
0:00:03.186 1M / 5186M INFO General
(simplification.cpp : 127) PROCEDURE == Initial cleaning
0:00:03.186 1M / 5186M INFO General
(graph_simplification.hpp : 662) Flanking coverage based
disconnection disabled
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Self conjugate edge remover
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Self conjugate edge remover
triggered 0 times
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Initial tip clipper
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Initial tip clipper triggered 0 times
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Initial ec remover
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Initial ec remover triggered 0 times
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Initial isolated edge remover
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Initial isolated edge remover
triggered 1 times
0:00:03.186 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Simplification (id: simplification)
0:00:03.186 1M / 5186M INFO General
(simplification.cpp : 368) Graph simplification started
0:00:03.186 1M / 5186M INFO General
(graph_simplification.hpp : 634) Creating parallel br instance
0:00:03.186 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 1
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 1 times
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.186 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.187 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 2
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.187 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 3
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.187 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 4
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.187 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 5
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.187 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 6
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.187 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 7
0:00:03.187 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.188 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 8
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.188 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 9
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.188 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 10
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.188 1M / 5186M INFO General
(simplification.cpp : 373) PROCEDURE == Simplification cycle,
iteration 11
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Low coverage edge remover
0:00:03.188 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Low coverage edge remover triggered
0 times
0:00:03.188 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Gap Closer (id: late_gapcloser)
0:00:03.194 10M / 5186M INFO General
(edge_index.hpp : 113) Size of edge index entries: 12/8
0:00:03.194 10M / 5186M INFO General
(gap_closer.cpp : 101) Total edges in tip neighborhood: 2
out of 2, length: 1890
0:00:03.194 10M / 5186M INFO General
(edge_index.hpp : 167) Using small index (max_id = 11)
0:00:03.194 10M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:03.195 10M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 945 kmers, 1456
bytes occupied (12.3259 bits per kmer).
0:00:03.195 10M / 5186M INFO General
(edge_index_builders.hpp : 265) Collecting edge information from
graph, this takes a while.
0:00:03.198 10M / 5186M INFO General
(sequence_mapper_notifier.h: 95) Total 2054 reads processed
0:00:03.201 10M / 5186M INFO General
(gap_closer.cpp : 452) Initializing gap closer
0:00:03.201 10M / 5186M INFO GapCloser
(gap_closer.cpp : 359) Closing short gaps
0:00:03.201 10M / 5186M INFO GapCloser
(gap_closer.cpp : 391) Closing short gaps complete: filled
0 gaps after checking 0 candidates
0:00:03.201 10M / 5186M INFO General
(gap_closer.cpp : 456) Gap closer done
0:00:03.202 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Simplification Cleanup (id:
simplification_cleanup)
0:00:03.202 1M / 5186M INFO General
(simplification.cpp : 176) PROCEDURE == Post simplification
0:00:03.202 1M / 5186M INFO General
(graph_simplification.hpp : 448) Disconnection of relatively low
covered edges disabled
0:00:03.202 1M / 5186M INFO General
(graph_simplification.hpp : 485) Complex tip clipping disabled
0:00:03.202 1M / 5186M INFO General
(graph_simplification.hpp : 634) Creating parallel br instance
0:00:03.202 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.202 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.202 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.202 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.202 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Tip clipper
0:00:03.202 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Tip clipper triggered 0 times
0:00:03.202 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Bulge remover
0:00:03.203 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Bulge remover triggered 0 times
0:00:03.203 1M / 5186M INFO General
(simplification.cpp : 327) Disrupting self-conjugate edges
0:00:03.203 1M / 5186M INFO Simplification
(parallel_processing.hpp : 167) Running Removing isolated edges
0:00:03.203 1M / 5186M INFO Simplification
(parallel_processing.hpp : 170) Removing isolated edges triggered 0
times
0:00:03.203 1M / 5186M INFO General
(simplification.cpp : 495) After simplification:
0:00:03.203 1M / 5186M INFO General
(simplification.cpp : 496) Average coverage = 140.62
0:00:03.203 1M / 5186M INFO General
(simplification.cpp : 497) Total length = 945
0:00:03.203 1M / 5186M INFO General
(simplification.cpp : 498) Median edge length: 945
0:00:03.203 1M / 5186M INFO General
(simplification.cpp : 499) Edges: 2
0:00:03.203 1M / 5186M INFO General
(simplification.cpp : 500) Vertices: 4
0:00:03.203 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Mismatch Correction (id:
mismatch_correction)
0:00:03.203 1M / 5186M INFO General
(graph_pack.cpp : 67) Index refill
0:00:03.203 1M / 5186M INFO General
(edge_index.hpp : 156) Using small index (max_id = 11)
0:00:03.203 1M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 395) Building perfect hash indices
0:00:03.203 1M / 5186M INFO K-mer Index Building
(kmer_index_builder.hpp : 431) Index built. Total 945 kmers, 1456
bytes occupied (12.3259 bits per kmer).
0:00:03.203 1M / 5186M INFO General
(edge_index_builders.hpp : 252) Collecting edge information from
graph, this takes a while.
0:00:03.203 1M / 5186M INFO General
(graph_pack.cpp : 77) Normalizing k-mer map. Total 0 kmers
to process
0:00:03.204 1M / 5186M INFO General
(graph_pack.cpp : 79) Normalizing done
0:00:03.204 1M / 5186M INFO General
(mismatch_correction.cpp : 400) Collect potential mismatches
0:00:03.204 1M / 5186M INFO General
(mismatch_correction.cpp : 192) Total 0 edges (out of 2) with 0
potential mismatch positions (-nan positions per edge)
0:00:03.204 1M / 5186M INFO General
(mismatch_correction.cpp : 402) Potential mismatches collected
0:00:03.207 1M / 5186M INFO General
(sequence_mapper_notifier.h: 95) Total 8216 reads processed
0:00:03.207 1M / 5186M INFO General
(mismatch_correction.cpp : 395) All edges processed
0:00:03.207 1M / 5186M INFO General
(mismatch_correction.cpp : 450) Corrected 0 nucleotides
0:00:03.207 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Contig Output (id: contig_output)
0:00:03.207 1M / 5186M INFO General
(contig_output.hpp : 16) Outputting contigs to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/before_rr.fasta
0:00:03.207 1M / 5186M INFO General
(contig_output_stage.cpp : 151) Writing GFA graph to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/assembly_graph_after_simplification.gfa
0:00:03.207 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Paired Information Counting (id:
late_pair_info_count)
0:00:03.207 1M / 5186M INFO General
(graph_pack.cpp : 77) Normalizing k-mer map. Total 0 kmers
to process
0:00:03.207 1M / 5186M INFO General
(graph_pack.cpp : 79) Normalizing done
0:00:03.207 1M / 5186M INFO General
(pair_info_count.cpp : 339) Min edge length for estimation: 945
0:00:03.207 1M / 5186M INFO General
(pair_info_count.cpp : 350) Estimating insert size for library #0
0:00:03.207 1M / 5186M INFO General
(pair_info_count.cpp : 202) Estimating insert size (takes a while)
0:00:03.307 273M / 5186M INFO General
(pair_info_count.cpp : 48) Selecting usual mapper
0:00:04.305 273M / 5186M INFO General
(sequence_mapper_notifier.h: 95) Total 2054 reads processed
0:00:04.523 273M / 5186M INFO General
(pair_info_count.cpp : 220) Edge pairs: 2
0:00:04.523 273M / 5186M INFO General
(pair_info_count.cpp : 222) 1636 paired reads (79.6495% of all)
aligned to long edges
0:00:04.523 1M / 5186M INFO General
(pair_info_count.cpp : 369) Insert size = 214.696, deviation =
10.4821, left quantile = 201, right quantile = 228, read length = 100
0:00:04.524 1M / 5186M INFO General
(pair_info_count.cpp : 390) Filtering data for library #0
0:00:04.525 1M / 5186M INFO General
(pair_info_count.cpp : 48) Selecting usual mapper
0:00:04.526 1M / 5186M INFO General
(sequence_mapper_notifier.h: 95) Total 2054 reads processed
0:00:04.526 1M / 5186M INFO General
(pair_info_count.cpp : 402) Mapping library #0
0:00:04.526 1M / 5186M INFO General
(pair_info_count.cpp : 404) Mapping paired reads (takes a while)
0:00:04.526 1M / 5186M INFO General
(pair_info_count.cpp : 299) Left insert size quantile 201, right
insert size quantile 228, filtering threshold 2, rounding threshold 0
0:00:04.533 10M / 5186M INFO General
(pair_info_count.cpp : 48) Selecting usual mapper
0:00:04.538 10M / 5186M INFO General
(sequence_mapper_notifier.h: 95) Total 2054 reads processed
0:00:04.543 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Distance Estimation (id:
distance_estimation)
0:00:04.543 1M / 5186M INFO General
(distance_estimation.cpp : 179) Processing library #0
0:00:04.543 1M / 5186M INFO General
(distance_estimation.cpp : 150) Weight Filter Done
0:00:04.543 1M / 5186M INFO DistanceEstimator
(distance_estimation.hpp : 116) Using SIMPLE distance estimator
0:00:04.544 1M / 5186M INFO General
(distance_estimation.cpp : 37) Filtering info
0:00:04.544 1M / 5186M INFO General
(pair_info_filters.hpp : 242) Start filtering; library index size: 2
0:00:04.544 1M / 5186M INFO General
(pair_info_filters.hpp : 263) Done filtering; library index size: 2
0:00:04.544 1M / 5186M INFO General
(distance_estimation.cpp : 156) Refining clustered pair information
0:00:04.544 1M / 5186M INFO General
(distance_estimation.cpp : 158) The refining of clustered pair
information has been finished
0:00:04.544 1M / 5186M INFO General
(distance_estimation.cpp : 160) Improving paired information
0:00:04.544 1M / 5186M INFO PairInfoImprover
(pair_info_improver.hpp : 104) Paired info stats: missing = 0;
contradictional = 0
0:00:04.544 1M / 5186M INFO PairInfoImprover
(pair_info_improver.hpp : 104) Paired info stats: missing = 0;
contradictional = 0
0:00:04.544 1M / 5186M INFO General
(distance_estimation.cpp : 104) Filling scaffolding index
0:00:04.544 1M / 5186M INFO DistanceEstimator
(distance_estimation.hpp : 116) Using SMOOTHING distance estimator
0:00:04.544 1M / 5186M INFO General
(distance_estimation.cpp : 37) Filtering info
0:00:04.544 1M / 5186M INFO General
(pair_info_filters.hpp : 242) Start filtering; library index size: 2
0:00:04.544 1M / 5186M INFO General
(pair_info_filters.hpp : 263) Done filtering; library index size: 2
0:00:04.544 1M / 5186M INFO General
(distance_estimation.cpp : 186) Clearing raw paired index
0:00:04.544 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Repeat Resolving (id: repeat_resolving)
0:00:04.544 1M / 5186M INFO General
(repeat_resolving.cpp : 87) Using Path-Extend repeat resolving
0:00:04.544 1M / 5186M INFO General
(launcher.cpp : 600) ExSPAnder repeat resolving tool started
0:00:04.545 1M / 5186M INFO General
(coverage_uniformity_analyz: 25) genomic coverage is 140.62
calculated of length 945
0:00:04.545 1M / 5186M WARN General
(launcher.cpp : 178) Your data seems to have high uniform
coverage depth. It is strongly recommended to use --isolate option.
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 418) Creating main extenders, unique edge
length = 2000
0:00:04.545 1M / 5186M INFO General
(extenders_logic.cpp : 334) Estimated coverage of library #0 is
140.62
0:00:04.545 1M / 5186M INFO General
(extenders_logic.cpp : 345) Creating extender; library index size: 2
0:00:04.545 1M / 5186M INFO General
(extenders_logic.cpp : 334) Estimated coverage of library #0 is
140.62
0:00:04.545 1M / 5186M INFO General
(extenders_logic.cpp : 345) Creating extender; library index size: 2
0:00:04.545 1M / 5186M INFO General
(extenders_logic.cpp : 543) Using 1 paired-end library
0:00:04.545 1M / 5186M INFO General
(extenders_logic.cpp : 544) Using 1 paired-end scaffolding library
0:00:04.545 1M / 5186M INFO General
(extenders_logic.cpp : 545) Using 0 single read libraries
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 447) Total number of extenders is 3
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 250) Finalizing paths
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 252) Deduplicating paths
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 256) Paths deduplicated
0:00:04.545 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 60) Removing overlaps
0:00:04.545 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 63) Sorting paths
0:00:04.545 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 70) Marking overlaps
0:00:04.545 1M / 5186M INFO OverlapRemover
(overlap_remover.hpp : 116) Marking start/end overlaps
0:00:04.545 1M / 5186M INFO OverlapRemover
(overlap_remover.hpp : 119) Marking remaining overlaps
0:00:04.545 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 73) Splitting paths
0:00:04.545 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 78) Deduplicating paths
0:00:04.545 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 80) Overlaps removed
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 273) Paths finalized
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 454) Closing gaps in paths
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 484) Gap closing completed
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 302) Traversing tandem repeats
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 312) Traversed 0 loops
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 250) Finalizing paths
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 252) Deduplicating paths
0:00:04.545 1M / 5186M INFO General
(launcher.cpp : 256) Paths deduplicated
0:00:04.545 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 60) Removing overlaps
0:00:04.545 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 63) Sorting paths
0:00:04.546 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 70) Marking overlaps
0:00:04.546 1M / 5186M INFO OverlapRemover
(overlap_remover.hpp : 116) Marking start/end overlaps
0:00:04.546 1M / 5186M INFO OverlapRemover
(overlap_remover.hpp : 119) Marking remaining overlaps
0:00:04.546 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 73) Splitting paths
0:00:04.546 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 78) Deduplicating paths
0:00:04.546 1M / 5186M INFO PEResolver
(pe_resolver.cpp : 80) Overlaps removed
0:00:04.546 1M / 5186M INFO General
(launcher.cpp : 273) Paths finalized
0:00:04.546 1M / 5186M INFO General
(launcher.cpp : 664) ExSPAnder repeat resolving tool finished
0:00:04.546 1M / 5186M INFO StageManager (stage.cpp
: 185) STAGE == Contig Output (id: contig_output)
0:00:04.546 1M / 5186M INFO General
(contig_output.hpp : 16) Outputting contigs to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/before_rr.fasta
0:00:04.546 1M / 5186M INFO General
(contig_output_stage.cpp : 151) Writing GFA graph to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/assembly_graph_with_scaffolds.gfa
0:00:04.546 1M / 5186M INFO General
(contig_output_stage.cpp : 165) Outputting FastG graph to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/assembly_graph.fastg
0:00:04.546 1M / 5186M INFO General
(contig_output_stage.cpp : 196) Breaking scaffolds
0:00:04.546 1M / 5186M INFO General
(contig_output_stage.cpp : 98) Outputting contigs to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/final_contigs.fasta
0:00:04.546 1M / 5186M INFO General
(contig_output_stage.cpp : 104) Outputting FastG paths to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/final_contigs.paths
0:00:04.546 1M / 5186M INFO General
(contig_output_stage.cpp : 98) Outputting contigs to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/scaffolds.fasta
0:00:04.546 1M / 5186M INFO General
(contig_output_stage.cpp : 104) Outputting FastG paths to
/tmp/tmp.Kw3upbPyKH/spades_test/K55/scaffolds.paths
0:00:04.546 1M / 5186M INFO General
(contig_output_stage.cpp : 111) Populating GFA with scaffold paths
0:00:04.546 1M / 5186M INFO General
(pipeline.cpp : 287) SPAdes finished
0:00:04.547 1M / 5186M INFO General (main.cpp
: 136) Assembling time: 0 hours 0 minutes 4 seconds
===== K55 finished.
===== Copy files started.
== Running: /usr/bin/python3
/usr/share/spades/spades_pipeline/scripts/copy_files.py
/tmp/tmp.Kw3upbPyKH/spades_test/K55/before_rr.fasta
/tmp/tmp.Kw3upbPyKH/spades_test/before_rr.fasta
/tmp/tmp.Kw3upbPyKH/spades_test/K55/assembly_graph_after_simplification.gfa
/tmp/tmp.Kw3upbPyKH/spades_test/assembly_graph_after_simplification.gfa
/tmp/tmp.Kw3upbPyKH/spades_test/K55/final_contigs.fasta
/tmp/tmp.Kw3upbPyKH/spades_test/contigs.fasta
/tmp/tmp.Kw3upbPyKH/spades_test/K55/first_pe_contigs.fasta
/tmp/tmp.Kw3upbPyKH/spades_test/first_pe_contigs.fasta
/tmp/tmp.Kw3upbPyKH/spades_test/K55/strain_graph.gfa
/tmp/tmp.Kw3upbPyKH/spades_test/strain_graph.gfa
/tmp/tmp.Kw3upbPyKH/spades_test/K55/scaffolds.fasta
/tmp/tmp.Kw3upbPyKH/spades_test/scaffolds.fasta
/tmp/tmp.Kw3upbPyKH/spades_test/K55/scaffolds.paths
/tmp/tmp.Kw3upbPyKH/spades_test/scaffolds.paths
/tmp/tmp.Kw3upbPyKH/spades_test/K55/assembly_graph_with_scaffolds.gfa
/tmp/tmp.Kw3upbPyKH/spades_test/assembly_graph_with_scaffolds.gfa
/tmp/tmp.Kw3upbPyKH/spades_test/K55/assembly_graph.fastg
/tmp/tmp.Kw3upbPyKH/spades_test/assembly_graph.fastg
/tmp/tmp.Kw3upbPyKH/spades_test/K55/final_contigs.paths
/tmp/tmp.Kw3upbPyKH/spades_test/contigs.paths
===== Copy files finished.
===== Assembling finished.
===== Check test started.
== Running: /usr/bin/python3
/usr/share/spades/spades_pipeline/scripts/check_test_script.py --mode
common --result_contigs_filename
/tmp/tmp.Kw3upbPyKH/spades_test/contigs.fasta
--result_scaffolds_filename /tmp/tmp.Kw3upbPyKH/spades_test/scaffolds.fasta
========= TEST PASSED CORRECTLY.
===== Check test finished.
===== Breaking scaffolds started.
== Running: /usr/bin/python3
/usr/share/spades/spades_pipeline/scripts/breaking_scaffolds_script.py
--result_scaffolds_filename
/tmp/tmp.Kw3upbPyKH/spades_test/scaffolds.fasta --misc_dir
/tmp/tmp.Kw3upbPyKH/spades_test/misc --threshold_for_breaking_scaffolds 3
===== Breaking scaffolds finished.
===== Terminate started.
===== Terminate finished.
* Corrected reads are in /tmp/tmp.Kw3upbPyKH/spades_test/corrected/
* Assembled contigs are in /tmp/tmp.Kw3upbPyKH/spades_test/contigs.fasta
* Assembled scaffolds are in
/tmp/tmp.Kw3upbPyKH/spades_test/scaffolds.fasta
* Paths in the assembly graph corresponding to the contigs are in
/tmp/tmp.Kw3upbPyKH/spades_test/contigs.paths
* Paths in the assembly graph corresponding to the scaffolds are in
/tmp/tmp.Kw3upbPyKH/spades_test/scaffolds.paths
* Assembly graph is in
/tmp/tmp.Kw3upbPyKH/spades_test/assembly_graph.fastg
* Assembly graph in GFA format is in
/tmp/tmp.Kw3upbPyKH/spades_test/assembly_graph_with_scaffolds.gfa
======= SPAdes pipeline finished WITH WARNINGS!
=== Error correction and assembling warnings:
* 0:00:04.545 1M / 5186M WARN General
(launcher.cpp : 178) Your data seems to have high uniform
coverage depth. It is strongly recommended to use --isolate option.
======= Warnings saved to /tmp/tmp.Kw3upbPyKH/spades_test/warnings.log
SPAdes log can be found here: /tmp/tmp.Kw3upbPyKH/spades_test/spades.log
Thank you for using SPAdes!
WARNING: TruSPAdes is deprecated since version 3.15
Generating truseq dataset from input directories:
/usr/share/spades/test_dataset_truspades
Printing dataset to /tmp/tmp.Kw3upbPyKH/spades_test_truspades/dataset.info
Dataset generated. See result in
/tmp/tmp.Kw3upbPyKH/spades_test_truspades/dataset.info
Launching truSPAdes assembly in 8 threads
You can find logs for separate barcodes in
/tmp/tmp.Kw3upbPyKH/spades_test_truspades/logs
Starting: BC_B
Starting: BC_A
Failed to finish: BC_A
Failed to finish: BC_B
2 barcodes failed to assemble
Warning: could not find assembly results for barcode BC_A
Warning: could not find assembly results for barcode BC_B
Assembled virtual long TruSeq reads can be found in
/tmp/tmp.Kw3upbPyKH/spades_test_truspades/TSLR.fasta
TruSPAdes launch successfully finished
TruSPAdes test launch failed: incorrect output files
autopkgtest [22:17:38]: test run-upstreams-tests
-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature
Type: application/pgp-signature
Size: 495 bytes
Desc: OpenPGP digital signature
URL: <http://alioth-lists.debian.net/pipermail/debian-med-packaging/attachments/20220528/3ad99e99/attachment-0001.sig>
More information about the Debian-med-packaging
mailing list