Error Code: -11 Explanation // Debug Mode?

klamkiew commented 6 years ago

Hi, I am using SPAdes on our working machines and it's working like a charm except for only one machine. I am not really able to find out why it fails for this specific machine (SPAdes version and python version are both the same on all machines) The spades.log is hinting towards the error code -11, but I did not find some explanation in the manual.

Furthermore the .log says the debug mode is turned off - I was looking for a switch/parameter to turn the debug mode 'on' in order to see what the problem might be, however, again I was not able to find something on the help page and the manual.

Thank you for any help :)

Cheers, Kevin

Command line: /mnt/prostlocal/programs/SPAdes/3.11.1/bin/spades.py  -1  /home/we75tan/Work/VRAP_2.0/VrAP/test_data/flash/flash.notCombined_1.fastq  -2  /home/we75tan/Work/VRAP_2.0/VrAP/test_data/flash/flash.notCombined_2.fastq  --only-assembler    -t  4   -o  /home/co68mol/spades_test   

System information:
  SPAdes version: 3.11.1
  Python version: 2.7.9
  OS: Linux-4.14.13-x86_64-with-debian-8.10

Output dir: /home/co68mol/spades_test
Mode: ONLY assembling (without read error correction)
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: ['/home/we75tan/Work/VRAP_2.0/VrAP/test_data/flash/flash.notCombined_1.fastq']
      right reads: ['/home/we75tan/Work/VRAP_2.0/VrAP/test_data/flash/flash.notCombined_2.fastq']
      interlaced reads: not specified
      single reads: not specified
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: /home/co68mol/spades_test/tmp
  Threads: 4
  Memory limit (in Gb): 250

======= SPAdes pipeline started. Log can be found here: /home/co68mol/spades_test/spades.log

===== Assembling started.

== Running assembler: K21

== Error ==  system call for: "['/mnt/prostlocal/programs/SPAdes/3.11.1/bin/spades', '/home/co68mol/spades_test/K21/configs/config.info']" finished abnormally, err code: -11

asl commented 6 years ago

Dear Kevin,

It looks like it cannot run the SPAdes binaries at all. Maybe (looking from /mnt) the filesystem is mounted in such way so it prohibits the execution of binaries?

I would suggest checking the system log.

klamkiew commented 6 years ago

Thanks for the hint with the SPAdes binaries. Turns out, they were accessible by our machine, however, the caused a segmentation fault. I downloaded the source code of SPAdes and re-compiled it by hand - now it works like a charm on all machines, not only 2 out of 3 ;) Thus, the issue can be closed, thanks again.

francis29029 commented 3 years ago

Hello, I was happy to find your thread regarding an error in spades. I have an similar one :

this is the error at the end of the log : == Error == system call for: "['/python/Anaconda3-2020.02-metagenome-atlas/AtlasDatabases/conda_envs/3218729d/bin/spades-core', 'R000085/assembly/K55/configs/config.info', 'R000085/assembly/K55/configs/mda_mode.info', 'R000085/assembly/K55/configs/meta_mode.info']" finished abnormally, err code: -11

does anyone see sth which can be explaining this error ?

thanks a lot

FRancis

======= SPAdes pipeline continued. Log can be found here: R000085/assembly/spades.log

Restored from Command line: /python/Anaconda3-2020.02-metagenome-atlas/AtlasDatabases/conda_envs/3218729d/bin/spades.py --threads 8 --memory 240 -o R000085/assembly -k auto --meta --pe1-1 R000085/assembly/reads/QC.errorcorr.merged_R1.fastq.gz --pe1-2 R000085/assembly/reads/QC.errorcorr.merged_R2.fastq.gz --pe1-s R000085/assembly/reads/QC.errorcorr.merged_se.fastq.gz --pe1-m R000085/assembly/reads/QC.errorcorr.merged_me.fastq.gz --only-assembler --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 300 -k auto --threads 8 --memory 350 -k auto with updated parameters: --threads 8 --memory 350 -k auto

Command line: /python/Anaconda3-2020.02-metagenome-atlas/AtlasDatabases/conda_envs/3218729d/bin/spades.py --threads 8 --memory 240 -o R000085/assembly -k auto --meta --pe1-1 R000085/assembly/reads/QC.errorcorr.merged_R1.fastq.gz --pe1-2 R000085/assembly/reads/QC.errorcorr.merged_R2.fastq.gz --pe1-s R000085/assembly/reads/QC.errorcorr.merged_se.fastq.gz --pe1-m R000085/assembly/reads/QC.errorcorr.merged_me.fastq.gz --only-assembler --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 240 -k auto --threads 8 --memory 300 -k auto --threads 8 --memory 350 -k auto --threads 8 --memory 350 -k auto

System information: SPAdes version: 3.13.1 Python version: 3.6.10 OS: Linux-3.10.0-1062.18.1.el7.x86_64-x86_64-with-redhat-7.8-Maipo

Output dir: R000085/assembly Mode: ONLY assembling (without read error correction) Debug mode is turned OFF

Dataset parameters: Metagenomic mode Reads: Library number: 1, library type: paired-end orientation: fr left reads: ['R000085/assembly/reads/QC.errorcorr.merged_R1.fastq.gz'] right reads: ['R000085/assembly/reads/QC.errorcorr.merged_R2.fastq.gz'] interlaced reads: not specified single reads: ['R000085/assembly/reads/QC.errorcorr.merged_se.fastq.gz'] merged reads: ['R000085/assembly/reads/QC.errorcorr.merged_me.fastq.gz'] Assembly parameters: k: [21, 33, 55] 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: R000085/assembly/tmp Threads: 8 Memory limit (in Gb): 350

===== Assembling started.

== Skipping assembler: K21 (already processed) Max read length detected as 126

== Skipping assembler: K33 (already processed)

== Running assembler: K55

0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /R000085/assembly/K55/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from R000085/assembly/K55/configs/mda_mode.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from R000085/assembly/K55/configs/meta_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 350 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from N/A, git revision N/A 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 (R000085/assembly/dataset.info) with K=55 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 8 0:00:00.000 4M / 4M INFO General (launch.hpp : 52) SPAdes started 0:00:00.000 4M / 4M INFO General (launch.hpp : 59) Starting from stage: construction 0:00:00.000 4M / 4M INFO General (launch.hpp : 66) Two-step RR enabled: 1 0:00:00.000 4M / 4M INFO General (launch.hpp : 77) Will need read mapping, kmer mapper will be attached 0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction 0:00:00.031 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected 0:00:00.851 4M / 4M INFO General (construction.cpp : 111) Max read length 643 0:00:00.851 4M / 4M INFO General (construction.cpp : 114) Max read length without merged 126 0:00:00.851 4M / 4M INFO General (construction.cpp : 117) Average read length 199.884 0:00:00.851 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.851 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 64 files using 8 threads. This might take a while. 0:00:00.851 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 32768 0:00:00.851 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 14.5832 Gb 0:00:00.851 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 524288 0:00:09.505 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 3150694 reads 0:00:18.212 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 6250852 reads 0:00:27.285 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 9349456 reads 0:00:36.199 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 12435937 reads 0:00:45.333 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 15530694 reads 0:00:54.436 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 18628781 reads 0:01:03.494 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 21721141 reads 0:01:12.394 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 24813661 reads 0:01:21.475 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 27909255 reads 0:01:30.891 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 32255812 reads 0:01:41.191 6G / 6G INFO General (kmer_splitters.hpp : 289) Processed 39891535 reads 0:01:43.845 6G / 6G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:02:17.932 32M / 6G INFO General (kmer_splitters.hpp : 308) Used 41069452 reads 0:02:17.932 32M / 6G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:02:37.650 32M / 6G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 474375535 kmers in total. 0:02:37.650 32M / 6G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:02:49.635 32M / 6G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:02:49.635 32M / 6G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:02:49.636 32M / 6G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. 0:02:49.636 32M / 6G INFO General (file_limit.hpp : 32) Open file limit set to 32768 0:02:49.636 32M / 6G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 14.582 Gb 0:02:49.636 32M / 6G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144 0:02:50.939 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 12331496 kmers 0:02:54.771 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 26041416 kmers 0:02:59.288 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 40060474 kmers 0:03:03.183 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 53278922 kmers 0:03:07.701 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 71174807 kmers 0:03:12.135 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 84811292 kmers 0:03:16.739 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 98877855 kmers 0:03:21.151 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 112095213 kmers 0:03:26.109 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 130430974 kmers 0:03:30.623 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 144053059 kmers 0:03:34.747 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 158126238 kmers 0:03:39.548 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 171354288 kmers 0:03:44.830 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 189737253 kmers 0:03:49.134 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 203358866 kmers 0:03:53.781 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 217427119 kmers 0:03:58.616 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 230640045 kmers 0:04:03.777 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 249038134 kmers 0:04:07.819 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 262664829 kmers 0:04:12.207 8G / 8G INFO General (kmer_splitters.hpp : 380) Processed 276735153 kmers 0:05:11.406 8G / 8G INFO General (kmer_splitters.hpp : 385) Used 474375791 kmers. 0:05:11.420 32M / 8G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:05:26.024 32M / 8G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 476201122 kmers in total. 0:05:26.024 32M / 8G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:05:37.293 32M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:06:03.204 256M / 8G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:06:10.169 256M / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 220823416 bytes occupied (3.70975 bits per kmer). 0:06:10.434 712M / 8G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:07:10.967 712M / 8G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:07:10.967 712M / 8G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:07:10.981 712M / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:08:39.432 1G / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 6592106 sequences extracted 0:09:17.339 1G / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:09:38.096 1G / 8G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 27 loops collected 0:09:42.443 2G / 8G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:09:42.443 2G / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:09:42.443 2G / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:10:09.632 3G / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 219973064 bytes occupied (3.70969 bits per kmer). 0:10:10.162 4G / 8G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:12:40.329 4G / 8G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:13:14.359 4G / 8G INFO General (construction.cpp : 464) Processed 8000000 edges 0:13:36.131 4G / 8G INFO General (construction.cpp : 464) Processed 13183253 edges 0:13:37.448 2G / 8G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:13:37.448 2G / 8G INFO General (graph_pack.hpp : 101) Index refill 0:13:37.449 2G / 8G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:13:37.449 2G / 8G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. 0:13:37.449 2G / 8G INFO General (file_limit.hpp : 32) Open file limit set to 32768 0:13:37.449 2G / 8G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 14.4867 Gb 0:13:37.449 2G / 8G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144 0:13:46.785 10G / 10G INFO General (edge_index_builders.hpp : 77) Processed 7053506 edges 0:13:56.014 10G / 10G INFO General (edge_index_builders.hpp : 77) Processed 13183261 edges 0:13:56.014 10G / 10G INFO General (edge_index_builders.hpp : 82) Used 13183261 sequences. 0:13:56.028 2G / 10G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:14:02.006 2G / 10G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 474375535 kmers in total. 0:14:02.006 2G / 10G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:14:13.921 2G / 10G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:14:40.240 2G / 10G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:14:47.290 2G / 10G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 219994746 bytes occupied (3.71005 bits per kmer). 0:14:53.648 13G / 13G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:15:27.510 13G / 13G INFO General (edge_index.hpp : 92) Index refilled 0:15:27.511 13G / 13G INFO General (gap_closer.cpp : 159) Preparing shift maps 0:15:37.829 14G / 14G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:15:41.084 14G / 14G INFO General (gap_closer.cpp : 138) Used 2726854 paired reads 0:15:41.084 14G / 14G INFO General (gap_closer.cpp : 140) Merging paired indices 0:15:46.349 13G / 14G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:16:12.720 13G / 14G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 27998 gaps after checking 274002 candidates 0:16:22.920 13G / 14G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:16:22.955 2G / 14G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:16:22.955 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:16:23.597 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 96 times 0:16:23.597 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper 0:16:53.196 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 1600867 times 0:16:53.196 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover 0:16:54.259 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 17378 times 0:16:54.259 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with low flanking coverage 0:16:55.370 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with low flanking coverage triggered 21004 times 0:16:55.370 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover 0:17:09.659 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 2070551 times 0:17:09.794 2G / 14G INFO StageManager (stage.cpp : 132) STAGE == Preliminary Simplification 0:17:09.794 2G / 14G INFO General (simplification.cpp : 357) Graph simplification started 0:17:09.795 2G / 14G INFO General (graph_simplification.hpp : 641) Creating parallel br instance 0:17:09.795 2G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:17:09.795 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:17:11.601 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 106862 times 0:17:11.601 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:17:49.670 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 155215 times 0:17:49.671 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:17:49.864 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 13 times 0:17:49.864 3G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:17:49.864 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:17:50.046 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 4381 times 0:17:50.046 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:17:50.093 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 116 times 0:17:50.093 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:17:53.080 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 71892 times 0:17:53.080 2G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:17:53.080 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:17:53.252 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 4225 times 0:17:53.252 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:17:54.372 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 3220 times 0:17:54.372 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:17:54.937 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 13811 times 0:17:54.937 2G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:17:54.937 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:17:55.033 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 953 times 0:17:55.033 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:17:55.717 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1088 times 0:17:55.717 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:17:55.822 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:17:55.822 2G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:17:55.822 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:17:55.825 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 9 times 0:17:55.825 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 1 times 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:17:55.826 2G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:17:55.826 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:17:55.826 2G / 14G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:17:55.826 2G / 14G INFO General (graph_pack.hpp : 101) Index refill 0:17:55.826 2G / 14G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:17:55.826 2G / 14G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. 0:17:55.827 2G / 14G INFO General (file_limit.hpp : 32) Open file limit set to 32768 0:17:55.827 2G / 14G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 14.4626 Gb 0:17:55.827 2G / 14G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144 0:18:02.121 10G / 14G INFO General (edge_index_builders.hpp : 77) Processed 595434 edges 0:18:02.122 10G / 14G INFO General (edge_index_builders.hpp : 82) Used 595434 sequences. 0:18:02.138 2G / 14G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:18:04.628 2G / 14G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 186241131 kmers in total. 0:18:04.629 2G / 14G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:18:09.231 2G / 14G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:18:16.614 2G / 14G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:18:19.462 2G / 14G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 86382732 bytes occupied (3.71058 bits per kmer). 0:18:21.978 7G / 14G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:18:33.592 7G / 14G INFO General (edge_index.hpp : 92) Index refilled 0:18:33.592 7G / 14G INFO General (gap_closer.cpp : 159) Preparing shift maps 0:18:34.227 7G / 14G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:19:09.686 7G / 14G INFO General (gap_closer.cpp : 138) Used 2726854 paired reads 0:19:09.686 7G / 14G INFO General (gap_closer.cpp : 140) Merging paired indices 0:19:10.266 7G / 14G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:19:11.417 7G / 14G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 1927 gaps after checking 27877 candidates 0:19:19.131 7G / 14G INFO StageManager (stage.cpp : 132) STAGE == Preliminary Paired Information Counting 0:19:22.627 7G / 14G INFO General (graph_pack.hpp : 109) Normalizing k-mer map. Total 20608032 kmers to process 0:19:35.421 7G / 14G INFO General (graph_pack.hpp : 111) Normalizing done 0:19:35.422 7G / 14G INFO General (pair_info_count.cpp : 323) Min edge length for estimation: 900 0:19:35.422 7G / 14G INFO General (pair_info_count.cpp : 334) Estimating insert size for library #0 0:19:35.422 7G / 14G INFO General (pair_info_count.cpp : 190) Estimating insert size (takes a while) 0:19:35.465 7G / 14G INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:19:54.431 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 200000 reads 0:19:54.474 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 400000 reads 0:19:54.627 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 600000 reads 0:19:54.648 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 800000 reads 0:19:57.236 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1000000 reads 0:19:57.398 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1200000 reads 0:20:09.674 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 2200000 reads 0:20:18.603 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 4200000 reads 0:20:29.115 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 8400000 reads 0:20:53.745 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 16800000 reads 0:20:59.285 7G / 14G INFO General (sequence_mapper_notifier.h: 98) Total 17764804 reads processed 0:20:59.479 7G / 14G INFO General (pair_info_count.cpp : 209) Edge pairs: 67108864 (rough upper limit) 0:20:59.479 7G / 14G INFO General (pair_info_count.cpp : 213) 12020228 paired reads (67.6632% of all) aligned to long edges 0:20:59.481 7G / 14G INFO General (pair_info_count.cpp : 357) Insert size = 246.084, deviation = 115.507, left quantile = 122, right quantile = 403, read length = 126 0:20:59.537 7G / 14G INFO General (pair_info_count.cpp : 374) Filtering data for library #0 0:20:59.537 7G / 14G INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:21:19.221 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 200000 reads 0:21:19.241 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 400000 reads 0:21:19.373 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 600000 reads 0:21:19.403 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 800000 reads 0:21:19.638 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1000000 reads 0:21:19.690 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1200000 reads 0:21:34.645 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 2200000 reads 0:21:40.417 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 4200000 reads 0:21:53.658 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 8400000 reads 0:22:18.840 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 16841202 reads 0:22:21.074 7G / 14G INFO General (sequence_mapper_notifier.h: 98) Total 17764804 reads processed 0:22:21.074 7G / 14G INFO General (pair_info_count.cpp : 386) Mapping library #0 0:22:21.074 7G / 14G INFO General (pair_info_count.cpp : 388) Mapping paired reads (takes a while) 0:22:21.074 7G / 14G INFO General (pair_info_count.cpp : 289) Left insert size quantile 122, right insert size quantile 403, filtering threshold 1, rounding threshold 0 0:22:21.081 7G / 14G INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:22:41.336 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 200000 reads 0:22:41.359 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 400000 reads 0:22:41.428 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 600000 reads 0:22:41.449 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 800000 reads 0:22:41.820 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1000000 reads 0:22:41.820 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1200000 reads 0:22:57.081 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 2200000 reads 0:23:03.046 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 4200000 reads 0:23:17.219 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 8400000 reads 0:23:43.683 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 16841202 reads 0:23:45.518 7G / 14G INFO General (sequence_mapper_notifier.h: 98) Total 17764804 reads processed 0:23:45.661 7G / 14G INFO StageManager (stage.cpp : 132) STAGE == Preliminary Distance Estimation 0:23:45.661 7G / 14G INFO General (distance_estimation.cpp : 173) Processing library #0 0:23:45.661 7G / 14G INFO General (distance_estimation.cpp : 149) Weight Filter Done 0:23:45.661 7G / 14G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SIMPLE distance estimator 0:23:50.655 7G / 14G INFO General (distance_estimation.cpp : 34) Filtering info 0:23:50.655 7G / 14G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 2707724 0:23:52.043 7G / 14G INFO General (pair_info_filters.hpp : 263) Done filtering 0:23:52.043 7G / 14G INFO General (distance_estimation.cpp : 156) Refining clustered pair information 0:23:52.913 7G / 14G INFO General (distance_estimation.cpp : 158) The refining of clustered pair information has been finished 0:23:52.913 7G / 14G INFO General (distance_estimation.cpp : 160) Improving paired information 0:23:57.819 7G / 14G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 187717; contradictional = 0 0:24:02.918 7G / 14G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 15739; contradictional = 0 0:24:02.918 7G / 14G INFO General (distance_estimation.cpp : 103) Filling scaffolding index 0:24:02.918 7G / 14G INFO DistanceEstimator (distance_estimation.hpp : 116) Using SMOOTHING distance estimator 0:24:06.813 7G / 14G INFO General (distance_estimation.cpp : 34) Filtering info 0:24:06.813 7G / 14G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 752948 0:24:07.198 7G / 14G INFO General (pair_info_filters.hpp : 263) Done filtering 0:24:07.198 7G / 14G INFO General (distance_estimation.cpp : 182) Clearing raw paired index 0:24:07.966 7G / 14G INFO StageManager (stage.cpp : 132) STAGE == Preliminary Repeat Resolving 0:24:07.966 7G / 14G INFO General (repeat_resolving.cpp : 56) Setting up preliminary path extend settings 0:24:07.966 7G / 14G INFO General (repeat_resolving.cpp : 69) Using Path-Extend repeat resolving 0:24:07.966 7G / 14G INFO General (launcher.cpp : 481) ExSPAnder repeat resolving tool started 0:24:10.035 8G / 14G INFO General (launcher.cpp : 392) Creating main extenders, unique edge length = 2000 0:24:10.526 8G / 14G INFO General (extenders_logic.cpp : 475) Using 1 paired-end library 0:24:10.526 8G / 14G INFO General (extenders_logic.cpp : 476) Using 1 paired-end scaffolding library 0:24:10.526 8G / 14G INFO General (extenders_logic.cpp : 477) Using 0 single read libraries 0:24:10.526 8G / 14G INFO General (launcher.cpp : 420) Total number of extenders is 3 0:24:10.526 8G / 14G INFO General (path_extender.hpp : 885) Processed 0 paths from 294529 (0%) 0:24:10.767 8G / 14G INFO General (path_extender.hpp : 883) Processed 128 paths from 294529 (0%) 0:24:11.029 8G / 14G INFO General (path_extender.hpp : 883) Processed 256 paths from 294529 (0%) 0:24:11.475 8G / 14G INFO General (path_extender.hpp : 883) Processed 512 paths from 294529 (0%) 0:24:12.192 8G / 14G INFO General (path_extender.hpp : 883) Processed 1024 paths from 294529 (0%) 0:24:13.437 8G / 14G INFO General (path_extender.hpp : 883) Processed 2048 paths from 294529 (0%) 0:24:15.027 8G / 14G INFO General (path_extender.hpp : 883) Processed 4096 paths from 294529 (1%) 0:24:17.365 8G / 14G INFO General (path_extender.hpp : 883) Processed 8192 paths from 294529 (2%) 0:24:20.403 8G / 14G INFO General (path_extender.hpp : 883) Processed 16384 paths from 294529 (5%) 0:24:23.721 8G / 14G INFO General (path_extender.hpp : 885) Processed 29453 paths from 294529 (10%) 0:24:24.354 8G / 14G INFO General (path_extender.hpp : 883) Processed 32768 paths from 294529 (11%) 0:24:27.834 9G / 14G INFO General (path_extender.hpp : 885) Processed 58906 paths from 294529 (20%) 0:24:28.511 9G / 14G INFO General (path_extender.hpp : 883) Processed 65536 paths from 294529 (22%) 0:24:32.411 9G / 14G INFO General (path_extender.hpp : 885) Processed 88359 paths from 294529 (30%) 0:24:39.438 9G / 14G INFO General (path_extender.hpp : 885) Processed 117812 paths from 294529 (40%) 0:24:43.139 9G / 14G INFO General (path_extender.hpp : 883) Processed 131072 paths from 294529 (44%) 0:24:48.099 9G / 14G INFO General (path_extender.hpp : 885) Processed 147265 paths from 294529 (50%) 0:24:56.331 10G / 14G INFO General (path_extender.hpp : 885) Processed 176718 paths from 294529 (60%) 0:25:05.107 10G / 14G INFO General (path_extender.hpp : 885) Processed 206171 paths from 294529 (70%) 0:25:15.636 10G / 14G INFO General (path_extender.hpp : 885) Processed 235624 paths from 294529 (80%) 0:25:21.114 10G / 14G INFO General (path_extender.hpp : 883) Processed 262144 paths from 294529 (89%) 0:25:21.489 10G / 14G INFO General (path_extender.hpp : 885) Processed 265077 paths from 294529 (90%) 0:25:23.498 10G / 14G INFO General (launcher.cpp : 234) Finalizing paths 0:25:23.498 10G / 14G INFO General (launcher.cpp : 236) Deduplicating paths 0:25:24.966 10G / 14G INFO General (launcher.cpp : 240) Paths deduplicated 0:25:24.967 10G / 14G INFO General (launcher.cpp : 247) Overlaps will not be removed 0:25:26.161 10G / 14G INFO General (launcher.cpp : 257) Paths finalized 0:25:26.161 10G / 14G INFO General (launcher.cpp : 427) Closing gaps in paths 0:25:27.409 10G / 14G INFO General (launcher.cpp : 455) Gap closing completed 0:25:27.966 10G / 14G INFO General (launcher.cpp : 286) Traversing tandem repeats 0:25:30.039 10G / 14G INFO General (launcher.cpp : 296) Traversed 104 loops 0:25:30.039 10G / 14G INFO General (launcher.cpp : 234) Finalizing paths 0:25:30.039 10G / 14G INFO General (launcher.cpp : 236) Deduplicating paths 0:25:30.476 10G / 14G INFO General (launcher.cpp : 240) Paths deduplicated 0:25:30.476 10G / 14G INFO General (launcher.cpp : 247) Overlaps will not be removed 0:25:31.085 10G / 14G INFO General (launcher.cpp : 257) Paths finalized 0:25:31.085 10G / 14G INFO General (launcher.cpp : 534) ExSPAnder repeat resolving tool finished 0:25:33.978 8G / 14G INFO General (repeat_resolving.cpp : 75) Restoring initial path extend settings 0:25:33.978 8G / 14G INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:25:33.978 8G / 14G INFO General (contig_output_stage.cpp : 45) Writing GFA to R000085/assembly//K55/assembly_graph_with_scaffolds.gfa 0:25:37.910 8G / 14G INFO General (contig_output.hpp : 22) Outputting contigs to R000085/assembly//K55/before_rr.fasta 0:25:41.368 8G / 14G INFO General (contig_output_stage.cpp : 56) Outputting FastG graph to R000085/assembly//K55/assembly_graph.fastg 0:25:54.471 8G / 14G INFO General (contig_output_stage.cpp : 20) Outputting FastG paths to R000085/assembly//K55/final_contigs.paths 0:26:02.241 8G / 14G INFO General (contig_output_stage.cpp : 20) Outputting FastG paths to R000085/assembly//K55/scaffolds.paths 0:26:08.898 8G / 14G INFO StageManager (stage.cpp : 132) STAGE == Second Phase Setup 0:26:08.898 8G / 14G INFO General (second_phase_setup.cpp : 20) Preparing second phase 0:26:10.288 7G / 14G INFO General (second_phase_setup.cpp : 28) Moving preliminary contigs from R000085/assembly//K55/final_contigs.fasta to R000085/assembly//K55/first_pe_contigs.fasta 0:26:10.288 7G / 14G INFO General (second_phase_setup.cpp : 40) Ready to run second phase 0:26:10.288 7G / 14G INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:26:10.359 2G / 14G INFO General (simplification.cpp : 357) Graph simplification started 0:26:10.359 2G / 14G INFO General (graph_simplification.hpp : 641) Creating parallel br instance 0:26:10.359 2G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:26:10.359 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:26:10.430 2G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times 0:26:10.430 2G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:26:23.583 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 39710 times 0:26:23.583 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:26:23.643 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:26:23.643 3G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:26:23.643 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:26:23.676 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 636 times 0:26:23.676 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 4 times 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:26:23.679 3G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 2 times 0:26:23.679 3G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:26:23.679 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:26:23.719 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 6 times 0:26:23.719 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:26:23.837 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 4 times 0:26:23.837 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:26:23.878 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:26:23.878 3G / 14G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:26:23.878 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:26:23.878 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:26:23.878 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:26:23.878 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:26:23.878 3G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:26:23.878 3G / 14G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:26:23.878 3G / 14G INFO StageManager (stage.cpp : 132) STAGE == Gap Closer 0:26:23.878 3G / 14G INFO General (graph_pack.hpp : 101) Index refill 0:26:23.879 3G / 14G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:26:23.879 3G / 14G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 128 files using 8 threads. This might take a while. 0:26:23.879 3G / 14G INFO General (file_limit.hpp : 32) Open file limit set to 32768 0:26:23.879 3G / 14G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 14.4572 Gb 0:26:23.879 3G / 14G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144 0:26:30.016 11G / 14G INFO General (edge_index_builders.hpp : 77) Processed 352188 edges 0:26:30.016 11G / 14G INFO General (edge_index_builders.hpp : 82) Used 352188 sequences. 0:26:30.032 3G / 14G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:26:32.199 3G / 14G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 182831460 kmers in total. 0:26:32.199 3G / 14G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:26:36.699 3G / 14G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:26:43.886 3G / 14G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:26:46.687 3G / 14G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 84787224 bytes occupied (3.70996 bits per kmer). 0:26:49.148 7G / 14G INFO General (edge_index_builders.hpp : 107) Collecting edge information from graph, this takes a while. 0:27:00.535 7G / 14G INFO General (edge_index.hpp : 92) Index refilled 0:27:00.536 7G / 14G INFO General (gap_closer.cpp : 159) Preparing shift maps 0:27:01.443 7G / 14G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while) 0:27:39.766 7G / 14G INFO General (gap_closer.cpp : 138) Used 2726854 paired reads 0:27:39.766 7G / 14G INFO General (gap_closer.cpp : 140) Merging paired indices 0:27:40.402 7G / 14G INFO GapCloser (gap_closer.cpp : 346) Closing short gaps 0:27:41.180 7G / 14G INFO GapCloser (gap_closer.cpp : 380) Closing short gaps complete: filled 9 gaps after checking 26742 candidates 0:27:41.317 7G / 14G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup 0:27:41.318 7G / 14G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification 0:27:41.318 7G / 14G INFO General (graph_simplification.hpp : 641) Creating parallel br instance 0:27:41.318 7G / 14G INFO General (graph_simplification.hpp : 641) Creating parallel br instance 0:27:41.318 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:27:56.918 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 2578 times 0:27:56.919 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:28:03.618 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 2111 times 0:28:03.618 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:28:03.915 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 58 times 0:28:03.915 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:28:33.501 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 4514 times 0:28:33.501 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:28:38.407 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1685 times 0:28:38.407 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:28:38.466 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times 0:28:38.466 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:28:38.935 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 331 times 0:28:38.935 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final bulge remover 0:28:54.899 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final bulge remover triggered 2468 times 0:28:54.899 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:28:55.731 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 30 times 0:28:55.731 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:28:55.972 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 55 times 0:28:55.973 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:28:56.591 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 337 times 0:28:56.591 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:28:56.653 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 9 times 0:28:56.653 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:28:58.085 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 318 times 0:28:58.085 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:28:58.667 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 373 times 0:28:58.667 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:28:58.709 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times 0:28:58.710 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:28:58.942 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 116 times 0:28:58.942 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final bulge remover 0:28:59.288 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final bulge remover triggered 59 times 0:28:59.288 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:28:59.485 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 2 times 0:28:59.486 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:28:59.582 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 12 times 0:28:59.582 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:28:59.615 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 11 times 0:28:59.615 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:28:59.669 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 1 times 0:28:59.669 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:29:00.356 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 33 times 0:29:00.356 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:29:00.366 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 11 times 0:29:00.366 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:29:00.367 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times 0:29:00.367 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:29:00.377 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 12 times 0:29:00.377 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final bulge remover 0:29:00.378 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final bulge remover triggered 0 times 0:29:00.378 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:29:00.378 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times 0:29:00.378 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:29:00.468 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 0 times 0:29:00.468 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:29:00.470 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 1 times 0:29:00.470 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:29:00.521 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times 0:29:00.521 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:29:01.104 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 0 times 0:29:01.104 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1 times 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final bulge remover 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final bulge remover triggered 0 times 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times 0:29:01.105 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:29:01.208 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 0 times 0:29:01.208 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:29:01.208 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 0 times 0:29:01.208 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:29:01.277 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times 0:29:01.277 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 0 times 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Final bulge remover 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Final bulge remover triggered 0 times 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:29:01.859 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times 0:29:01.859 7G / 14G INFO General (simplification.cpp : 326) Running Hidden EC remover (meta) 0:29:02.145 7G / 14G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges 0:29:02.540 7G / 14G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges 0:29:08.395 7G / 14G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 28177 times 0:29:08.396 7G / 14G INFO General (simplification.cpp : 470) Counting average coverage 0:29:08.519 7G / 14G INFO General (simplification.cpp : 476) Average coverage = 15.149 0:29:08.519 7G / 14G INFO StageManager (stage.cpp : 132) STAGE == Mismatch Correction 0:29:08.519 7G / 14G INFO General (graph_pack.hpp : 109) Normalizing k-mer map. Total 30766057 kmers to process 0:29:29.279 7G / 14G INFO General (graph_pack.hpp : 111) Normalizing done 0:33:53.824 8G / 14G INFO General (mismatch_shall_not_pass.hp: 189) Finished collecting potential mismatches positions 0:34:06.131 7G / 14G INFO General (mismatch_shall_not_pass.hp: 290) All edges processed 0:34:06.472 7G / 14G INFO General (mismatch_correction.cpp : 27) Corrected 1994 nucleotides 0:34:06.473 7G / 14G INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:34:06.473 7G / 14G INFO General (contig_output_stage.cpp : 45) Writing GFA to R000085/assembly//K55/assembly_graph_with_scaffolds.gfa 0:34:08.170 7G / 14G INFO General (contig_output.hpp : 22) Outputting contigs to R000085/assembly//K55/before_rr.fasta 0:34:10.178 7G / 14G INFO General (contig_output_stage.cpp : 56) Outputting FastG graph to R000085/assembly//K55/assembly_graph.fastg 0:34:16.423 7G / 14G INFO General (contig_output.hpp : 22) Outputting contigs to R000085/assembly//K55/final_contigs.fasta 0:34:18.413 7G / 14G INFO StageManager (stage.cpp : 132) STAGE == Paired Information Counting 0:34:19.433 7G / 14G INFO General (graph_pack.hpp : 109) Normalizing k-mer map. Total 30918959 kmers to process 0:34:40.963 7G / 14G INFO General (graph_pack.hpp : 111) Normalizing done 0:34:40.963 7G / 14G INFO General (pair_info_count.cpp : 323) Min edge length for estimation: 900 0:34:40.963 7G / 14G INFO General (pair_info_count.cpp : 334) Estimating insert size for library #0 0:34:40.963 7G / 14G INFO General (pair_info_count.cpp : 190) Estimating insert size (takes a while) 0:34:41.005 7G / 14G INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:35:02.374 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 200000 reads 0:35:02.395 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 400000 reads 0:35:02.623 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 600000 reads 0:35:02.717 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 800000 reads 0:35:03.227 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1000000 reads 0:35:03.276 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1200000 reads 0:35:19.471 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 2200000 reads 0:35:26.173 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 4200000 reads 0:35:41.898 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 8400000 reads 0:36:12.074 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 16841202 reads 0:36:15.016 7G / 14G INFO General (sequence_mapper_notifier.h: 98) Total 17764804 reads processed 0:36:15.213 7G / 14G INFO General (pair_info_count.cpp : 209) Edge pairs: 67108864 (rough upper limit) 0:36:15.213 7G / 14G INFO General (pair_info_count.cpp : 213) 13255605 paired reads (74.6172% of all) aligned to long edges 0:36:15.215 7G / 14G INFO General (pair_info_count.cpp : 357) Insert size = 246.903, deviation = 116.032, left quantile = 122, right quantile = 403, read length = 126 0:36:15.272 7G / 14G INFO General (pair_info_count.cpp : 374) Filtering data for library #0 0:36:15.273 7G / 14G INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:36:36.575 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 200000 reads 0:36:36.579 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 400000 reads 0:36:36.630 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 600000 reads 0:36:36.640 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 800000 reads 0:36:37.338 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1000000 reads 0:36:37.344 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1200000 reads 0:36:53.134 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 2200000 reads 0:37:00.152 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 4200000 reads 0:37:14.926 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 8400000 reads 0:37:42.969 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 16800000 reads 0:37:48.367 7G / 14G INFO General (sequence_mapper_notifier.h: 98) Total 17764804 reads processed 0:37:48.367 7G / 14G INFO General (pair_info_count.cpp : 386) Mapping library #0 0:37:48.367 7G / 14G INFO General (pair_info_count.cpp : 388) Mapping paired reads (takes a while) 0:37:48.368 7G / 14G INFO General (pair_info_count.cpp : 289) Left insert size quantile 122, right insert size quantile 403, filtering threshold 1, rounding threshold 0 0:37:48.374 7G / 14G INFO General (pair_info_count.cpp : 39) Selecting usual mapper 0:38:10.068 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 200000 reads 0:38:10.075 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 400000 reads 0:38:10.208 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 600000 reads 0:38:10.283 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 800000 reads 0:38:10.817 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1000000 reads 0:38:10.827 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 1200000 reads 0:38:26.935 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 2200000 reads 0:38:34.097 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 4200000 reads 0:38:49.868 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 8400000 reads 0:39:21.101 7G / 14G INFO General (sequence_mapper_notifier.h: 80) Processed 16841202 reads 0:39:25.104 7G / 14G INFO General (sequence_mapper_notifier.h: 98) Total 17764804 reads processed 0:39:25.157 7G / 14G INFO General (pair_info_count.cpp : 330) Mapping contigs library #1 0:39:25.157 7G / 14G INFO General (pair_info_count.cpp : 39) Selecting usual mapper

== Error == system call for: "['/python/Anaconda3-2020.02-metagenome-atlas/AtlasDatabases/conda_envs/3218729d/bin/spades-core', 'R000085/assembly/K55/configs/config.info', 'R000085/assembly/K55/configs/mda_mode.info', 'R000085/assembly/K55/configs/meta_mode.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.

ablab / spades

Error Code: -11 Explanation // Debug Mode? #94