search

ablab / spades

SPAdes Genome Assembler
http://ablab.github.io/spades/
Other
737 stars 134 forks source link

metaspades.py v3.13.0 is getting stuck at parallel_processing.hpp #337

Closed jolespin closed 5 years ago

jolespin commented 5 years ago

I'm running metaspades on my dataset and it's getting stuck at a particular stage. This happened yesterday as it was running overnight. I tried again today and it's been running for a few hours with no progress at this stage.

$ cat spades.log
Command line: /usr/local/devel/ANNOTATION/jespinoz/anaconda/envs/mage_env/bin/metaspades.py -1  /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_1.fastq.gz -2  /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_2.fastq.gz -o  /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output  --tmp-dir   /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/tmp --threads   16  --memory    250

System information:
  SPAdes version: 3.13.0
  Python version: 2.7.15
  OS: Linux-2.6.32-696.18.7.el6.x86_64-x86_64-with-centos-6.4-Final

Output dir: /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output
Mode: read error correction and assembling
Debug mode is turned OFF

Dataset parameters:
  Metagenomic mode
  Reads:
    Library number: 1, library type: paired-end
      orientation: fr
      left reads: ['/local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_1.fastq.gz']
      right reads: ['/local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_2.fastq.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: [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: /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/tmp
  Threads: 16
  Memory limit (in Gb): 250

======= SPAdes pipeline started. Log can be found here: /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/spades.log

===== Read error correction started.

== Running read error correction tool: /usr/local/devel/ANNOTATION/jespinoz/anaconda/envs/mage_env/share/spades-3.13.0-0/bin/spades-hammer /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/corrected/configs/config.info

  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  75)   Starting BayesHammer, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  76)   Loading config from /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/corrected/configs/config.info
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  78)   Maximum # of threads to use (adjusted due to OMP capabilities): 16
  0:00:00.001     4M / 4M    INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 250 Gb
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  86)   Trying to determine PHRED offset
  0:00:00.002     4M / 4M    INFO    General                 (main.cpp                  :  92)   Determined value is 33
  0:00:00.002     4M / 4M    INFO    General                 (hammer_tools.cpp          :  36)   Hamming graph threshold tau=1, k=21, subkmer positions = [ 0 10 ]
  0:00:00.002     4M / 4M    INFO    General                 (main.cpp                  : 113)   Size of aux. kmer data 24 bytes
     === ITERATION 0 begins ===
  0:00:00.002     4M / 4M    INFO   K-mer Counting           (kmer_data.cpp             : 280)   Estimating k-mer count
  0:00:00.103   260M / 260M  INFO   K-mer Counting           (kmer_data.cpp             : 285)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_1.fastq.gz
  0:00:01.127   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 294)   Processed 158612 reads
  0:00:01.127   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 285)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_2.fastq.gz
  0:00:01.904   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 294)   Processed 317224 reads
  0:00:01.904   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 299)   Total 317224 reads processed
  0:00:03.483   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 306)   Estimated 59328843 distinct kmers
  0:00:03.484    64M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 311)   Filtering singleton k-mers
35 8 0
nslots: 134217728
bits per slot: 8 range: 0000000800000000
  0:00:03.484   228M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 317)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_1.fastq.gz
  0:00:26.758   228M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 326)   Processed 158612 reads
  0:00:26.758   228M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 317)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_2.fastq.gz
  0:00:48.419   228M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 326)   Processed 317224 reads
  0:00:48.419   228M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 331)   Total 317224 reads processed
  0:00:48.427   228M / 320M  INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:00:48.427   228M / 320M  INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:00:48.430   228M / 320M  INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:00:48.430   228M / 320M  INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20369 Gb
  0:00:48.430   228M / 320M  INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 262144
  0:00:50.250     9G / 9G    INFO   K-mer Splitting          (kmer_data.cpp             :  97)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_1.fastq.gz
  0:00:53.325     9G / 9G    INFO   K-mer Splitting          (kmer_data.cpp             : 107)   Processed 158612 reads
  0:00:53.325     9G / 9G    INFO   K-mer Splitting          (kmer_data.cpp             :  97)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_2.fastq.gz
  0:00:55.948     9G / 9G    INFO   K-mer Splitting          (kmer_data.cpp             : 107)   Processed 317224 reads
  0:00:55.948     9G / 9G    INFO   K-mer Splitting          (kmer_data.cpp             : 112)   Total 317224 reads processed
  0:00:57.050   228M / 9G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:00:58.531   228M / 9G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 9525666 kmers in total.
  0:00:58.531   228M / 9G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:00:59.562   228M / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:01:00.368   228M / 9G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
  0:01:00.695   228M / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 4425344 bytes occupied (3.71656 bits per kmer).
  0:01:00.700    64M / 9G    INFO   K-mer Counting           (kmer_data.cpp             : 356)   Arranging kmers in hash map order
  0:01:01.449   216M / 9G    INFO    General                 (main.cpp                  : 148)   Clustering Hamming graph.
  0:01:05.436   216M / 9G    INFO    General                 (main.cpp                  : 155)   Extracting clusters
  0:01:08.629   216M / 9G    INFO    General                 (main.cpp                  : 167)   Clustering done. Total clusters: 8752441
  0:01:08.629   140M / 9G    INFO   K-mer Counting           (kmer_data.cpp             : 376)   Collecting K-mer information, this takes a while.
  0:01:08.731   360M / 9G    INFO   K-mer Counting           (kmer_data.cpp             : 382)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_1.fastq.gz
  0:01:09.982   360M / 9G    INFO   K-mer Counting           (kmer_data.cpp             : 382)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_2.fastq.gz
  0:01:10.944   360M / 9G    INFO   K-mer Counting           (kmer_data.cpp             : 389)   Collection done, postprocessing.
  0:01:10.974   360M / 9G    INFO   K-mer Counting           (kmer_data.cpp             : 403)   There are 9525666 kmers in total. Among them 85714 (0.899822%) are singletons.
  0:01:10.974   360M / 9G    INFO    General                 (main.cpp                  : 173)   Subclustering Hamming graph
  0:01:12.480   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 649)   Subclustering done. Total 29 non-read kmers were generated.
  0:01:12.480   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 650)   Subclustering statistics:
  0:01:12.481   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 651)     Total singleton hamming clusters: 8458088. Among them 7710854 (91.1655%) are good
  0:01:12.481   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 652)     Total singleton subclusters: 16175. Among them 16163 (99.9258%) are good
  0:01:12.481   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 653)     Total non-singleton subcluster centers: 330341. Among them 322433 (97.6061%) are good
  0:01:12.481   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 654)     Average size of non-trivial subcluster: 3.23188 kmers
  0:01:12.481   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 655)     Average number of sub-clusters per non-singleton cluster: 1.17721
  0:01:12.481   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 656)     Total solid k-mers: 8049450
  0:01:12.481   360M / 9G    INFO   Hamming Subclustering    (kmer_cluster.cpp          : 657)     Substitution probabilities: [4,4]((0.952853,0.00859363,0.0205306,0.0180225),(0.0218613,0.909166,0.014851,0.0541215),(0.0447181,0.0124557,0.916961,0.0258654),(0.0154606,0.0163697,0.00703758,0.961132))
  0:01:12.498   360M / 9G    INFO    General                 (main.cpp                  : 178)   Finished clustering.
  0:01:12.498   360M / 9G    INFO    General                 (main.cpp                  : 197)   Starting solid k-mers expansion in 16 threads.
  0:01:14.379   360M / 9G    INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 0 produced 98695 new k-mers.
  0:01:15.816   360M / 9G    INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 1 produced 7375 new k-mers.
  0:01:17.067   360M / 9G    INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 2 produced 908 new k-mers.
  0:01:18.317   360M / 9G    INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 3 produced 176 new k-mers.
  0:01:19.568   360M / 9G    INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 4 produced 10 new k-mers.
  0:01:20.822   360M / 9G    INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 5 produced 0 new k-mers.
  0:01:20.822   360M / 9G    INFO    General                 (main.cpp                  : 222)   Solid k-mers finalized
  0:01:20.822   360M / 9G    INFO    General                 (hammer_tools.cpp          : 220)   Starting read correction in 16 threads.
  0:01:20.822   360M / 9G    INFO    General                 (hammer_tools.cpp          : 233)   Correcting pair of reads: /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_1.fastq.gz and /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/preprocessing/kneaddata_repaired_2.fastq.gz
  0:01:22.322   628M / 9G    INFO    General                 (hammer_tools.cpp          : 168)   Prepared batch 0 of 158612 reads.
  0:01:24.205   628M / 9G    INFO    General                 (hammer_tools.cpp          : 175)   Processed batch 0
  0:01:24.582   628M / 9G    INFO    General                 (hammer_tools.cpp          : 185)   Written batch 0
  0:01:25.183   360M / 9G    INFO    General                 (hammer_tools.cpp          : 274)   Correction done. Changed 79240 bases in 40222 reads.
  0:01:25.183   360M / 9G    INFO    General                 (hammer_tools.cpp          : 275)   Failed to correct 777 bases out of 43849010.
  0:01:25.185    64M / 9G    INFO    General                 (main.cpp                  : 255)   Saving corrected dataset description to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/corrected/corrected.yaml
  0:01:25.189    64M / 9G    INFO    General                 (main.cpp                  : 262)   All done. Exiting.

== Compressing corrected reads (with pigz)

== Dataset description file was created: /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/corrected/corrected.yaml

===== Read error correction finished.

===== Assembling started.

== Running assembler: K21

  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/K21/configs/config.info
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/K21/configs/mda_mode.info
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/K21/configs/meta_mode.info
  0:00:00.000     4M / 4M    INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 250 Gb
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  87)   Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
  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 (/local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/dataset.info) with K=21
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  90)   Maximum # of threads to use (adjusted due to OMP capabilities): 16
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  51)   SPAdes started
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  58)   Starting from stage: construction
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  65)   Two-step RR enabled: 0
  0:00:00.000     4M / 4M    INFO   StageManager             (stage.cpp                 : 132)   STAGE == de Bruijn graph construction
  0:00:00.005     4M / 4M    INFO    General                 (read_converter.hpp        :  77)   Converting reads to binary format for library #0 (takes a while)
  0:00:00.005     4M / 4M    INFO    General                 (read_converter.hpp        :  78)   Converting paired reads
  0:00:00.537    80M / 80M   INFO    General                 (binary_converter.hpp      :  93)   16384 reads processed
  0:00:00.854    96M / 96M   INFO    General                 (binary_converter.hpp      :  93)   32768 reads processed
  0:00:01.372   124M / 124M  INFO    General                 (binary_converter.hpp      :  93)   65536 reads processed
  0:00:02.108   148M / 148M  INFO    General                 (binary_converter.hpp      : 117)   91564 reads written
  0:00:02.209     4M / 148M  INFO    General                 (read_converter.hpp        :  87)   Converting single reads
  0:00:02.429   140M / 148M  INFO    General                 (binary_converter.hpp      :  93)   16384 reads processed
  0:00:02.534   140M / 148M  INFO    General                 (binary_converter.hpp      : 117)   23171 reads written
  0:00:02.546     4M / 148M  INFO    General                 (read_converter.hpp        :  95)   Converting merged reads
  0:00:02.659   132M / 148M  INFO    General                 (binary_converter.hpp      : 117)   0 reads written
  0:00:02.783     4M / 148M  INFO    General                 (construction.cpp          : 111)   Max read length 151
  0:00:02.784     4M / 148M  INFO    General                 (construction.cpp          : 117)   Average read length 137.673
  0:00:02.784     4M / 148M  INFO    General                 (stage.cpp                 : 101)   PROCEDURE == k+1-mer counting
  0:00:02.786     4M / 148M  INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:00:02.788     4M / 148M  INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:00:02.788     4M / 148M  INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20825 Gb
  0:00:02.788     4M / 148M  INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 262144
  0:00:07.254     8G / 8G    INFO    General                 (kmer_splitters.hpp        : 289)   Processed 412598 reads
  0:00:07.255     8G / 8G    INFO    General                 (kmer_splitters.hpp        : 295)   Adding contigs from previous K
  0:00:08.472    64M / 8G    INFO    General                 (kmer_splitters.hpp        : 308)   Used 412598 reads
  0:00:08.472    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:00:10.172    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 15619984 kmers in total.
  0:00:10.172    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:00:11.283    64M / 8G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Extension index construction
  0:00:11.285    64M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:00:11.285    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:00:11.287    64M / 8G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:00:11.287    64M / 8G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20703 Gb
  0:00:11.287    64M / 8G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 262144
  0:00:16.443     8G / 8G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 15619984 kmers
  0:00:16.443     8G / 8G    INFO    General                 (kmer_splitters.hpp        : 385)   Used 15619984 kmers.
  0:00:17.686    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:00:19.459    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 15627500 kmers in total.
  0:00:19.459    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:00:20.513    64M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:00:21.857    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
  0:00:22.368    64M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 7254648 bytes occupied (3.71379 bits per kmer).
  0:00:22.383    80M / 8G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
  0:00:23.440    80M / 8G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
  0:00:23.443    80M / 8G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Early tip clipping
  0:00:23.443    80M / 8G    INFO    General                 (construction.cpp          : 253)   Early tip clipper length bound set as (RL - K)
  0:00:23.443    80M / 8G    INFO   Early tip clipping       (early_simplification.hpp  : 181)   Early tip clipping
  0:00:24.794    80M / 8G    INFO   Early tip clipping       (early_simplification.hpp  : 184)   2372508 22-mers were removed by early tip clipper
  0:00:24.794    80M / 8G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Condensing graph
  0:00:24.838    80M / 8G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 355)   Extracting unbranching paths
  0:00:25.699    88M / 8G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 374)   Extracting unbranching paths finished. 223655 sequences extracted
  0:00:26.155    88M / 8G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 310)   Collecting perfect loops
  0:00:26.464    88M / 8G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 343)   Collecting perfect loops finished. 360 loops collected
  0:00:26.636   148M / 8G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Filling coverage indices (PHM)
  0:00:26.636   148M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:00:26.636   148M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:00:27.091   152M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 7251184 bytes occupied (3.7138 bits per kmer).
  0:00:27.122   212M / 8G    INFO    General                 (construction.cpp          : 388)   Collecting k-mer coverage information from reads, this takes a while.
  0:00:27.702   212M / 8G    INFO    General                 (construction.cpp          : 508)   Filling coverage and flanking coverage from PHM
  0:00:28.172   212M / 8G    INFO    General                 (construction.cpp          : 464)   Processed 447813 edges
  0:00:28.251   128M / 8G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Raw Simplification
  0:00:28.251   128M / 8G    INFO    General                 (simplification.cpp        : 128)   PROCEDURE == InitialCleaning
  0:00:28.251   128M / 8G    INFO    General                 (graph_simplification.hpp  : 662)   Flanking coverage based disconnection disabled
  0:00:28.251   128M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Self conjugate edge remover
  0:00:28.286   128M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Self conjugate edge remover triggered 0 times
  0:00:28.286   128M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial tip clipper
  0:00:28.405   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial tip clipper triggered 5148 times
  0:00:28.405   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial ec remover
  0:00:29.333   128M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial ec remover triggered 30494 times
  0:00:29.334   128M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial isolated edge remover
  0:00:29.494   128M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial isolated edge remover triggered 29491 times
  0:00:29.502   124M / 8G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Simplification
  0:00:29.502   124M / 8G    INFO    General                 (simplification.cpp        : 357)   Graph simplification started
  0:00:29.502   124M / 8G    INFO    General                 (graph_simplification.hpp  : 634)   Creating parallel br instance
  0:00:29.502   124M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 1
  0:00:29.502   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:29.558   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 4163 times
  0:00:29.558   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:30.888   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 10525 times
  0:00:30.888   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:30.902   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:00:30.902   124M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 2
  0:00:30.902   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:30.915   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 684 times
  0:00:30.915   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:30.924   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 22 times
  0:00:30.924   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:30.969   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 1952 times
  0:00:30.969   124M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 3
  0:00:30.969   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:30.973   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 214 times
  0:00:30.973   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:31.067   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 313 times
  0:00:31.067   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:31.115   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 2194 times
  0:00:31.115   124M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 4
  0:00:31.115   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:31.125   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 127 times
  0:00:31.125   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:31.351   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 295 times
  0:00:31.351   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:31.359   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 2 times
  0:00:31.359   124M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 5
  0:00:31.359   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 2 times
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:00:31.360   124M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 6
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:00:31.360   124M / 8G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Simplification Cleanup
  0:00:31.360   124M / 8G    INFO    General                 (simplification.cpp        : 196)   PROCEDURE == Post simplification
  0:00:31.360   124M / 8G    INFO    General                 (graph_simplification.hpp  : 634)   Creating parallel br instance
  0:00:31.360   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:00:31.545   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 1351 times
  0:00:31.545   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:00:31.684   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 310 times
  0:00:31.684   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:00:31.706   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 114 times
  0:00:31.706   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:00:32.112   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 39 times
  0:00:32.112   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:32.123   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 165 times
  0:00:32.123   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:00:32.133   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 142 times
  0:00:32.133   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:32.192   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 80 times
  0:00:32.192   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:00:32.207   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:00:32.207   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:00:32.243   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 37 times
  0:00:32.243   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:00:32.306   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 12 times
  0:00:32.306   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:00:32.317   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 2 times
  0:00:32.317   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:00:32.658   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 2 times
  0:00:32.658   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:32.666   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 12 times
  0:00:32.666   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:00:32.673   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 0 times
  0:00:32.673   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:32.712   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 4 times
  0:00:32.712   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:00:32.724   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:00:32.724   124M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:00:32.749   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 3 times
  0:00:32.749   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:00:32.751   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 1 times
  0:00:32.752   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:00:32.761   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 0 times
  0:00:32.761   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:00:33.086   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 0 times
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 1 times
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 0 times
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:00:33.087   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:00:33.112   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 0 times
  0:00:33.113   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:00:33.113   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 0 times
  0:00:33.113   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:00:33.122   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 0 times
  0:00:33.122   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 0 times
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 0 times
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:00:33.447   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:00:33.447   120M / 8G    INFO    General                 (simplification.cpp        : 326)   Running Hidden EC remover (meta)
  0:00:33.454   120M / 8G    INFO    General                 (simplification.cpp        : 330)   Disrupting self-conjugate edges
  0:00:33.503   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Removing isolated edges
  0:00:33.512   120M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Removing isolated edges triggered 323 times
  0:00:33.512   120M / 8G    INFO    General                 (simplification.cpp        : 470)   Counting average coverage
  0:00:33.534   120M / 8G    INFO    General                 (simplification.cpp        : 476)   Average coverage = 1.84496
  0:00:33.534   120M / 8G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Contig Output
  0:00:33.534   120M / 8G    INFO    General                 (contig_output_stage.cpp   :  40)   Writing GFA to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/assembly_graph_with_scaffolds.gfa
  0:00:33.868   120M / 8G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/before_rr.fasta
  0:00:34.306   120M / 8G    INFO    General                 (contig_output_stage.cpp   :  51)   Outputting FastG graph to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/assembly_graph.fastg
  0:00:35.101   120M / 8G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/simplified_contigs.fasta
  0:00:35.397   120M / 8G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/final_contigs.fasta
  0:00:35.712   120M / 8G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Contig Output
  0:00:35.712   120M / 8G    INFO    General                 (contig_output_stage.cpp   :  40)   Writing GFA to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/assembly_graph_with_scaffolds.gfa
  0:00:35.931   120M / 8G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/before_rr.fasta
  0:00:36.224   120M / 8G    INFO    General                 (contig_output_stage.cpp   :  51)   Outputting FastG graph to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/assembly_graph.fastg
  0:00:36.961   120M / 8G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/simplified_contigs.fasta
  0:00:37.260   120M / 8G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output//K21/final_contigs.fasta
  0:00:37.582   120M / 8G    INFO    General                 (launch.hpp                : 149)   SPAdes finished
  0:00:37.715    64M / 8G    INFO    General                 (main.cpp                  : 109)   Assembling time: 0 hours 0 minutes 37 seconds
Max read length detected as 151

== Running assembler: K33

  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/K33/configs/config.info
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/K33/configs/mda_mode.info
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/K33/configs/meta_mode.info
  0:00:00.000     4M / 4M    INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 250 Gb
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  87)   Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
  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 (/local/ifs3_scratch/METAGENOMICS/jespinoz/plastisphere/metagenome_output/NT-01-E-TROPICAL-PUNCH-LABEL-PE-H503H705-3_S19/intermediate/metaspades_output/dataset.info) with K=33
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  90)   Maximum # of threads to use (adjusted due to OMP capabilities): 16
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  51)   SPAdes started
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  58)   Starting from stage: construction
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  65)   Two-step RR enabled: 0
  0:00:00.000     4M / 4M    INFO   StageManager             (stage.cpp                 : 132)   STAGE == de Bruijn graph construction
  0:00:00.006     4M / 4M    INFO    General                 (read_converter.hpp        :  59)   Binary reads detected
  0:00:00.025     4M / 4M    INFO    General                 (construction.cpp          : 111)   Max read length 151
  0:00:00.025     4M / 4M    INFO    General                 (construction.cpp          : 117)   Average read length 137.673
  0:00:00.025     4M / 4M    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == k+1-mer counting
  0:00:00.027     4M / 4M    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:00:00.029     4M / 4M    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:00:00.029     4M / 4M    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20825 Gb
  0:00:00.029     4M / 4M    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 131072
  0:00:05.449     8G / 8G    INFO    General                 (kmer_splitters.hpp        : 289)   Processed 412598 reads
  0:00:05.449     8G / 8G    INFO    General                 (kmer_splitters.hpp        : 295)   Adding contigs from previous K
  0:00:10.260    64M / 8G    INFO    General                 (kmer_splitters.hpp        : 308)   Used 412598 reads
  0:00:10.260    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:00:12.344    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 15155813 kmers in total.
  0:00:12.344    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:00:13.852    64M / 8G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Extension index construction
  0:00:13.855    64M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:00:13.855    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:00:13.858    64M / 8G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:00:13.858    64M / 8G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20703 Gb
  0:00:13.858    64M / 8G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 131072
  0:00:19.778     8G / 8G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 15155813 kmers
  0:00:19.778     8G / 8G    INFO    General                 (kmer_splitters.hpp        : 385)   Used 15155813 kmers.
  0:00:21.022    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:00:23.075    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 15210808 kmers in total.
  0:00:23.075    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:00:24.577    64M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:00:25.784    64M / 8G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
  0:00:26.787    64M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 7061600 bytes occupied (3.71399 bits per kmer).
  0:00:26.804    80M / 8G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
  0:00:27.716    80M / 8G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
  0:00:27.719    80M / 8G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Early tip clipping
  0:00:27.719    80M / 8G    INFO    General                 (construction.cpp          : 253)   Early tip clipper length bound set as (RL - K)
  0:00:27.719    80M / 8G    INFO   Early tip clipping       (early_simplification.hpp  : 181)   Early tip clipping
  0:00:29.220    80M / 8G    INFO   Early tip clipping       (early_simplification.hpp  : 184)   1997010 34-mers were removed by early tip clipper
  0:00:29.220    80M / 8G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Condensing graph
  0:00:29.267    80M / 8G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 355)   Extracting unbranching paths
  0:00:29.940    88M / 8G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 374)   Extracting unbranching paths finished. 149163 sequences extracted
  0:00:30.307    88M / 8G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 310)   Collecting perfect loops
  0:00:30.559    88M / 8G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 343)   Collecting perfect loops finished. 221 loops collected
  0:00:30.650   104M / 8G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Filling coverage indices (PHM)
  0:00:30.650   104M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:00:30.650   104M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:00:31.048   152M / 8G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 7035896 bytes occupied (3.7139 bits per kmer).
  0:00:31.070   212M / 8G    INFO    General                 (construction.cpp          : 388)   Collecting k-mer coverage information from reads, this takes a while.
  0:00:31.608   212M / 8G    INFO    General                 (construction.cpp          : 508)   Filling coverage and flanking coverage from PHM
  0:00:32.192   212M / 8G    INFO    General                 (construction.cpp          : 464)   Processed 298707 edges
  0:00:32.277    80M / 8G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Raw Simplification
  0:00:32.277    80M / 8G    INFO    General                 (simplification.cpp        : 128)   PROCEDURE == InitialCleaning
  0:00:32.277    80M / 8G    INFO    General                 (graph_simplification.hpp  : 662)   Flanking coverage based disconnection disabled
  0:00:32.277    80M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Self conjugate edge remover
  0:00:32.296    80M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Self conjugate edge remover triggered 19 times
  0:00:32.296    80M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial tip clipper
  0:00:32.370    72M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial tip clipper triggered 5086 times
  0:00:32.370    72M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial ec remover
  0:00:32.644    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial ec remover triggered 11741 times
  0:00:32.644    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial isolated edge remover
  0:00:32.852    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial isolated edge remover triggered 45415 times
  0:00:32.855    76M / 8G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Simplification
  0:00:32.855    76M / 8G    INFO    General                 (simplification.cpp        : 357)   Graph simplification started
  0:00:32.855    76M / 8G    INFO    General                 (graph_simplification.hpp  : 634)   Creating parallel br instance
  0:00:32.855    76M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 1
  0:00:32.856    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:32.885    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 1864 times
  0:00:32.885    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:33.461    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 3902 times
  0:00:33.461    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:33.471    80M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 9 times
  0:00:33.471    80M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 2
  0:00:33.471    80M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:33.476    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 207 times
  0:00:33.476    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:33.477    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 10 times
  0:00:33.477    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:33.488    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 512 times
  0:00:33.488    76M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 3
  0:00:33.488    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:33.489    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 43 times
  0:00:33.489    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:33.529    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 51 times
  0:00:33.529    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:33.560    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 1515 times
  0:00:33.560    76M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 4
  0:00:33.560    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:33.568    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 35 times
  0:00:33.568    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:33.718    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 139 times
  0:00:33.718    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:33.724    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:00:33.724    76M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 5
  0:00:33.724    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 3 times
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:00:33.725    76M / 8G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 6
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:00:33.725    76M / 8G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Simplification Cleanup
  0:00:33.725    76M / 8G    INFO    General                 (simplification.cpp        : 196)   PROCEDURE == Post simplification
  0:00:33.725    76M / 8G    INFO    General                 (graph_simplification.hpp  : 634)   Creating parallel br instance
  0:00:33.725    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:00:33.821    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 738 times
  0:00:33.821    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:00:33.929    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 302 times
  0:00:33.929    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:00:33.943    72M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 77 times
  0:00:33.943    72M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:00:34.341    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 38 times
  0:00:34.341    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:00:34.356    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 172 times
  0:00:34.356    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:00:34.369    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 97 times
  0:00:34.369    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:00:34.440    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 37 times
  0:00:34.440    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:00:34.451    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:00:34.451    76M / 8G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:00:34.492    72M / 8G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 24 times
asl commented 5 years ago

Does it stuck always at the same stage?

jolespin commented 5 years ago

I'm trying w/ a larger dataset and it keeps getting stuck at this stage:

Do you think I'm not allocating enough memory? 

Command line: /usr/local/devel/ANNOTATION/jespinoz/anaconda/envs/mage_env/bin/metaspades.py -1  /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz -2  /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz -o  /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output  --tmp-dir   /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/tmp --threads   16  --memory    250

System information:
  SPAdes version: 3.13.0
  Python version: 2.7.15
  OS: Linux-2.6.32-696.18.7.el6.x86_64-x86_64-with-centos-6.4-Final

Output dir: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output
Mode: read error correction and assembling
Debug mode is turned OFF

Dataset parameters:
  Metagenomic mode
  Reads:
    Library number: 1, library type: paired-end
      orientation: fr
      left reads: ['/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz']
      right reads: ['/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.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: [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: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/tmp
  Threads: 16
  Memory limit (in Gb): 250

======= SPAdes pipeline started. Log can be found here: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/spades.log

===== Read error correction started.

== Running read error correction tool: /usr/local/devel/ANNOTATION/jespinoz/anaconda/envs/mage_env/share/spades-3.13.0-0/bin/spades-hammer /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/corrected/configs/config.info

  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  75)   Starting BayesHammer, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  76)   Loading config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/corrected/configs/config.info
  0:00:00.002     4M / 4M    INFO    General                 (main.cpp                  :  78)   Maximum # of threads to use (adjusted due to OMP capabilities): 16
  0:00:00.002     4M / 4M    INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 250 Gb
  0:00:00.002     4M / 4M    INFO    General                 (main.cpp                  :  86)   Trying to determine PHRED offset
  0:00:00.003     4M / 4M    INFO    General                 (main.cpp                  :  92)   Determined value is 33
  0:00:00.003     4M / 4M    INFO    General                 (hammer_tools.cpp          :  36)   Hamming graph threshold tau=1, k=21, subkmer positions = [ 0 10 ]
  0:00:00.003     4M / 4M    INFO    General                 (main.cpp                  : 113)   Size of aux. kmer data 24 bytes
     === ITERATION 0 begins ===
  0:00:00.003     4M / 4M    INFO   K-mer Counting           (kmer_data.cpp             : 280)   Estimating k-mer count
  0:00:00.162   260M / 260M  INFO   K-mer Counting           (kmer_data.cpp             : 285)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz
  0:00:28.679   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 294)   Processed 6432954 reads
  0:00:28.679   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 285)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz
  0:00:56.634   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 294)   Processed 12865908 reads
  0:00:56.634   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 299)   Total 12865908 reads processed
  0:00:58.240   320M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 306)   Estimated 1071469545 distinct kmers
  0:00:58.240    64M / 320M  INFO   K-mer Counting           (kmer_data.cpp             : 311)   Filtering singleton k-mers
39 8 0
nslots: 2147483648
bits per slot: 8 range: 0000008000000000
  0:00:58.240     2G / 2G    INFO   K-mer Counting           (kmer_data.cpp             : 317)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz
  0:12:13.615     2G / 2G    INFO   K-mer Counting           (kmer_data.cpp             : 326)   Processed 6432954 reads
  0:12:13.615     2G / 2G    INFO   K-mer Counting           (kmer_data.cpp             : 317)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz
  0:20:28.724     2G / 2G    INFO   K-mer Counting           (kmer_data.cpp             : 326)   Processed 12865908 reads
  0:20:28.724     2G / 2G    INFO   K-mer Counting           (kmer_data.cpp             : 331)   Total 12865908 reads processed
  0:20:28.733     2G / 2G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:20:28.733     2G / 2G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:20:28.735     2G / 2G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:20:28.735     2G / 2G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.15422 Gb
  0:20:28.735     2G / 2G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 262144
  0:20:30.450    11G / 11G   INFO   K-mer Splitting          (kmer_data.cpp             :  97)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz
  0:21:04.713    11G / 11G   INFO   K-mer Splitting          (kmer_data.cpp             : 107)   Processed 4681537 reads
  0:21:20.441    11G / 11G   INFO   K-mer Splitting          (kmer_data.cpp             : 107)   Processed 6432954 reads
  0:21:20.441    11G / 11G   INFO   K-mer Splitting          (kmer_data.cpp             :  97)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz
  0:21:55.655    11G / 11G   INFO   K-mer Splitting          (kmer_data.cpp             : 107)   Processed 11120116 reads
  0:22:10.806    11G / 11G   INFO   K-mer Splitting          (kmer_data.cpp             : 107)   Processed 12865908 reads
  0:22:10.806    11G / 11G   INFO   K-mer Splitting          (kmer_data.cpp             : 112)   Total 12865908 reads processed
  0:22:12.399     2G / 11G   INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:22:36.269     2G / 11G   INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 520078412 kmers in total.
  0:22:36.269     2G / 11G   INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:22:59.683     2G / 11G   INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:23:19.099     2G / 11G   INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
  0:23:32.427     2G / 11G   INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 241186474 bytes occupied (3.71 bits per kmer).
  0:23:32.444   268M / 11G   INFO   K-mer Counting           (kmer_data.cpp             : 356)   Arranging kmers in hash map order
  0:23:54.326     8G / 11G   INFO    General                 (main.cpp                  : 148)   Clustering Hamming graph.
  0:31:57.230     8G / 11G   INFO    General                 (main.cpp                  : 155)   Extracting clusters
  0:33:48.379     8G / 29G   INFO    General                 (main.cpp                  : 167)   Clustering done. Total clusters: 475169316
  0:33:48.389     4G / 29G   INFO   K-mer Counting           (kmer_data.cpp             : 376)   Collecting K-mer information, this takes a while.
  0:33:52.375    15G / 29G   INFO   K-mer Counting           (kmer_data.cpp             : 382)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz
  0:35:11.926    15G / 29G   INFO   K-mer Counting           (kmer_data.cpp             : 382)   Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz
  0:36:30.321    15G / 29G   INFO   K-mer Counting           (kmer_data.cpp             : 389)   Collection done, postprocessing.
  0:36:31.878    15G / 29G   INFO   K-mer Counting           (kmer_data.cpp             : 403)   There are 520078412 kmers in total. Among them 1076972 (0.207079%) are singletons.
  0:36:31.878    15G / 29G   INFO    General                 (main.cpp                  : 173)   Subclustering Hamming graph
  0:37:11.208    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 649)   Subclustering done. Total 3293 non-read kmers were generated.
  0:37:11.209    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 650)   Subclustering statistics:
  0:37:11.209    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 651)     Total singleton hamming clusters: 450072772. Among them 439704338 (97.6963%) are good
  0:37:11.209    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 652)     Total singleton subclusters: 6381387. Among them 6381166 (99.9965%) are good
  0:37:11.209    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 653)     Total non-singleton subcluster centers: 25550695. Among them 25376104 (99.3167%) are good
  0:37:11.209    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 654)     Average size of non-trivial subcluster: 2.7401 kmers
  0:37:11.209    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 655)     Average number of sub-clusters per non-singleton cluster: 1.27237
  0:37:11.209    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 656)     Total solid k-mers: 471461608
  0:37:11.209    15G / 29G   INFO   Hamming Subclustering    (kmer_cluster.cpp          : 657)     Substitution probabilities: [4,4]((0.943725,0.0129303,0.0311364,0.0122081),(0.0104258,0.939102,0.0154774,0.034995),(0.0305376,0.0131951,0.943911,0.0123565),(0.0103756,0.0261745,0.0108634,0.952586))
  0:37:11.841    15G / 29G   INFO    General                 (main.cpp                  : 178)   Finished clustering.
  0:37:11.841    15G / 29G   INFO    General                 (main.cpp                  : 197)   Starting solid k-mers expansion in 16 threads.
  0:38:12.726    15G / 29G   INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 0 produced 10945282 new k-mers.
  0:39:13.013    15G / 29G   INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 1 produced 230322 new k-mers.
  0:40:14.321    15G / 29G   INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 2 produced 6909 new k-mers.
  0:41:15.324    15G / 29G   INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 3 produced 173 new k-mers.
  0:42:13.388    15G / 29G   INFO    General                 (main.cpp                  : 218)   Solid k-mers iteration 4 produced 0 new k-mers.
  0:42:13.388    15G / 29G   INFO    General                 (main.cpp                  : 222)   Solid k-mers finalized
  0:42:13.388    15G / 29G   INFO    General                 (hammer_tools.cpp          : 220)   Starting read correction in 16 threads.
  0:42:13.388    15G / 29G   INFO    General                 (hammer_tools.cpp          : 233)   Correcting pair of reads: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz and /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz
  0:42:26.318    17G / 29G   INFO    General                 (hammer_tools.cpp          : 168)   Prepared batch 0 of 1600000 reads.
  0:42:45.970    17G / 29G   INFO    General                 (hammer_tools.cpp          : 175)   Processed batch 0
  0:42:49.614    17G / 29G   INFO    General                 (hammer_tools.cpp          : 185)   Written batch 0
  0:43:00.344    18G / 29G   INFO    General                 (hammer_tools.cpp          : 168)   Prepared batch 1 of 1600000 reads.
  0:43:20.157    18G / 29G   INFO    General                 (hammer_tools.cpp          : 175)   Processed batch 1
  0:43:23.462    18G / 29G   INFO    General                 (hammer_tools.cpp          : 185)   Written batch 1
  0:43:34.892    18G / 29G   INFO    General                 (hammer_tools.cpp          : 168)   Prepared batch 2 of 1600000 reads.
  0:43:54.669    18G / 29G   INFO    General                 (hammer_tools.cpp          : 175)   Processed batch 2
  0:43:58.017    18G / 29G   INFO    General                 (hammer_tools.cpp          : 185)   Written batch 2
  0:44:08.499    18G / 29G   INFO    General                 (hammer_tools.cpp          : 168)   Prepared batch 3 of 1600000 reads.
  0:44:28.296    18G / 29G   INFO    General                 (hammer_tools.cpp          : 175)   Processed batch 3
  0:44:31.577    18G / 29G   INFO    General                 (hammer_tools.cpp          : 185)   Written batch 3
  0:44:32.168    18G / 29G   INFO    General                 (hammer_tools.cpp          : 168)   Prepared batch 4 of 32954 reads.
  0:44:32.879    18G / 29G   INFO    General                 (hammer_tools.cpp          : 175)   Processed batch 4
  0:44:32.985    18G / 29G   INFO    General                 (hammer_tools.cpp          : 185)   Written batch 4
  0:44:38.779    15G / 29G   INFO    General                 (hammer_tools.cpp          : 274)   Correction done. Changed 2673607 bases in 1735725 reads.
  0:44:38.779    15G / 29G   INFO    General                 (hammer_tools.cpp          : 275)   Failed to correct 33781 bases out of 1888692442.
  0:44:38.873    64M / 29G   INFO    General                 (main.cpp                  : 255)   Saving corrected dataset description to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/corrected/corrected.yaml
  0:44:38.879    64M / 29G   INFO    General                 (main.cpp                  : 262)   All done. Exiting.

== Compressing corrected reads (with pigz)

== Dataset description file was created: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/corrected/corrected.yaml

===== Read error correction finished.

===== Assembling started.

== Running assembler: K21

  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K21/configs/config.info
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K21/configs/mda_mode.info
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K21/configs/meta_mode.info
  0:00:00.001     4M / 4M    INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 250 Gb
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  87)   Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  88)   Maximum k-mer length: 128
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  89)   Assembling dataset (/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/dataset.info) with K=21
  0:00:00.001     4M / 4M    INFO    General                 (main.cpp                  :  90)   Maximum # of threads to use (adjusted due to OMP capabilities): 16
  0:00:00.001     4M / 4M    INFO    General                 (launch.hpp                :  51)   SPAdes started
  0:00:00.001     4M / 4M    INFO    General                 (launch.hpp                :  58)   Starting from stage: construction
  0:00:00.001     4M / 4M    INFO    General                 (launch.hpp                :  65)   Two-step RR enabled: 0
  0:00:00.002     4M / 4M    INFO   StageManager             (stage.cpp                 : 132)   STAGE == de Bruijn graph construction
  0:00:00.006     4M / 4M    INFO    General                 (read_converter.hpp        :  77)   Converting reads to binary format for library #0 (takes a while)
  0:00:00.006     4M / 4M    INFO    General                 (read_converter.hpp        :  78)   Converting paired reads
  0:00:00.753    84M / 84M   INFO    General                 (binary_converter.hpp      :  93)   16384 reads processed
  0:00:01.080   100M / 100M  INFO    General                 (binary_converter.hpp      :  93)   32768 reads processed
  0:00:01.581   128M / 128M  INFO    General                 (binary_converter.hpp      :  93)   65536 reads processed
  0:00:02.589   192M / 192M  INFO    General                 (binary_converter.hpp      :  93)   131072 reads processed
  0:00:04.708   316M / 316M  INFO    General                 (binary_converter.hpp      :  93)   262144 reads processed
  0:00:07.726   564M / 564M  INFO    General                 (binary_converter.hpp      :  93)   524288 reads processed
  0:00:16.031   948M / 948M  INFO    General                 (binary_converter.hpp      :  93)   1048576 reads processed
  0:00:29.822   952M / 952M  INFO    General                 (binary_converter.hpp      :  93)   2097152 reads processed
  0:00:57.595   952M / 952M  INFO    General                 (binary_converter.hpp      :  93)   4194304 reads processed
  0:01:24.735   544M / 952M  INFO    General                 (binary_converter.hpp      : 117)   6032100 reads written
  0:01:25.351     4M / 952M  INFO    General                 (read_converter.hpp        :  87)   Converting single reads
  0:01:25.761   140M / 952M  INFO    General                 (binary_converter.hpp      :  93)   16384 reads processed
  0:01:26.007   148M / 952M  INFO    General                 (binary_converter.hpp      :  93)   32768 reads processed
  0:01:26.475   160M / 952M  INFO    General                 (binary_converter.hpp      :  93)   65536 reads processed
  0:01:27.141   192M / 952M  INFO    General                 (binary_converter.hpp      :  93)   131072 reads processed
  0:01:28.430   244M / 952M  INFO    General                 (binary_converter.hpp      : 117)   241905 reads written
  0:01:28.568     4M / 952M  INFO    General                 (read_converter.hpp        :  95)   Converting merged reads
  0:01:28.765   132M / 952M  INFO    General                 (binary_converter.hpp      : 117)   0 reads written
  0:01:29.413     4M / 952M  INFO    General                 (construction.cpp          : 111)   Max read length 151
  0:01:29.413     4M / 952M  INFO    General                 (construction.cpp          : 117)   Average read length 146.97
  0:01:29.413     4M / 952M  INFO    General                 (stage.cpp                 : 101)   PROCEDURE == k+1-mer counting
  0:01:29.416     4M / 952M  INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:01:29.419     4M / 952M  INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:01:29.419     4M / 952M  INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20825 Gb
  0:01:29.419     4M / 952M  INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 262144
  0:01:52.194     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 289)   Processed 16824210 reads
  0:02:04.101     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 289)   Processed 24612210 reads
  0:02:04.101     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 295)   Adding contigs from previous K
  0:02:05.261    64M / 9G    INFO    General                 (kmer_splitters.hpp        : 308)   Used 24612210 reads
  0:02:05.261    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:02:18.029    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 439103884 kmers in total.
  0:02:18.029    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:02:37.249    64M / 9G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Extension index construction
  0:02:37.251    64M / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:02:37.251    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:02:37.254    64M / 9G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:02:37.254    64M / 9G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20703 Gb
  0:02:37.254    64M / 9G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 262144
  0:02:42.452     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 4662698 kmers
  0:02:46.550     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 31901089 kmers
  0:02:50.769     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 59336276 kmers
  0:02:55.046     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 86784959 kmers
  0:02:59.050     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 114227892 kmers
  0:03:03.219     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 141665859 kmers
  0:03:07.121     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 169119197 kmers
  0:03:11.473     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 196553308 kmers
  0:03:15.789     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 224006554 kmers
  0:03:20.087     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 251452534 kmers
  0:03:24.177     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 278894562 kmers
  0:03:28.455     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 306338516 kmers
  0:03:32.567     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 333788643 kmers
  0:03:36.566     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 361228445 kmers
  0:03:41.049     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 388665161 kmers
  0:03:45.314     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 416112975 kmers
  0:03:49.396     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 439104140 kmers
  0:03:49.396     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 385)   Used 439104140 kmers.
  0:03:50.406    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:04:05.865    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 438410056 kmers in total.
  0:04:05.865    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:04:24.632    64M / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:04:40.621   256M / 9G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
  0:04:52.192   256M / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 203299576 bytes occupied (3.70976 bits per kmer).
  0:04:52.590   676M / 9G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
  0:05:21.873   676M / 9G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
  0:05:21.877   676M / 9G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Early tip clipping
  0:05:21.877   676M / 9G    INFO    General                 (construction.cpp          : 253)   Early tip clipper length bound set as (RL - K)
  0:05:21.877   676M / 9G    INFO   Early tip clipping       (early_simplification.hpp  : 181)   Early tip clipping
  0:06:23.715   676M / 9G    INFO   Early tip clipping       (early_simplification.hpp  : 184)   38221328 22-mers were removed by early tip clipper
  0:06:23.715   676M / 9G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Condensing graph
  0:06:23.761   676M / 9G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 355)   Extracting unbranching paths
  0:07:04.534     1G / 9G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 374)   Extracting unbranching paths finished. 5316310 sequences extracted
  0:07:20.115     1G / 9G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 310)   Collecting perfect loops
  0:07:30.722     1G / 9G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 343)   Collecting perfect loops finished. 1181 loops collected
  0:07:33.372     2G / 9G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Filling coverage indices (PHM)
  0:07:33.372     2G / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:07:33.372     2G / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:07:46.439     2G / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 203641438 bytes occupied (3.71013 bits per kmer).
  0:07:47.456     4G / 9G    INFO    General                 (construction.cpp          : 388)   Collecting k-mer coverage information from reads, this takes a while.
  0:08:31.532     4G / 9G    INFO    General                 (construction.cpp          : 508)   Filling coverage and flanking coverage from PHM
  0:08:55.807     4G / 9G    INFO    General                 (construction.cpp          : 464)   Processed 10633265 edges
  0:08:57.806     1G / 9G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Raw Simplification
  0:08:57.806     1G / 9G    INFO    General                 (simplification.cpp        : 128)   PROCEDURE == InitialCleaning
  0:08:57.808     1G / 9G    INFO    General                 (graph_simplification.hpp  : 662)   Flanking coverage based disconnection disabled
  0:08:57.808     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Self conjugate edge remover
  0:08:58.364     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Self conjugate edge remover triggered 0 times
  0:08:58.364     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial tip clipper
  0:08:59.932     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial tip clipper triggered 56328 times
  0:08:59.932     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial ec remover
  0:09:19.055     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial ec remover triggered 670453 times
  0:09:19.055     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Initial isolated edge remover
  0:09:20.306     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Initial isolated edge remover triggered 148366 times
  0:09:20.566     1G / 9G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Simplification
  0:09:20.566     1G / 9G    INFO    General                 (simplification.cpp        : 357)   Graph simplification started
  0:09:20.566     1G / 9G    INFO    General                 (graph_simplification.hpp  : 634)   Creating parallel br instance
  0:09:20.566     1G / 9G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 1
  0:09:20.566     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:09:22.610     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 139121 times
  0:09:22.610     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:10:13.983     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 364778 times
  0:10:13.983     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:10:14.412     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:10:14.412     1G / 9G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 2
  0:10:14.412     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:10:14.873     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 8047 times
  0:10:14.873     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:10:15.550     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 169 times
  0:10:15.550     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:10:16.561     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 34595 times
  0:10:16.561     1G / 9G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 3
  0:10:16.561     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:10:16.625     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 1788 times
  0:10:16.625     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:10:18.882     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 6687 times
  0:10:18.882     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:10:21.346     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 81644 times
  0:10:21.346     1G / 9G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 4
  0:10:21.346     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:10:21.629     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 2443 times
  0:10:21.629     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:10:30.533     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 13709 times
  0:10:30.533     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:10:30.814     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 11 times
  0:10:30.814     1G / 9G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 5
  0:10:30.814     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:10:30.845     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 55 times
  0:10:30.845     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:10:30.856     1G / 9G    INFO    General                 (simplification.cpp        : 362)   PROCEDURE == Simplification cycle, iteration 6
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Low coverage edge remover
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Low coverage edge remover triggered 0 times
  0:10:30.856     1G / 9G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Simplification Cleanup
  0:10:30.856     1G / 9G    INFO    General                 (simplification.cpp        : 196)   PROCEDURE == Post simplification
  0:10:30.856     1G / 9G    INFO    General                 (graph_simplification.hpp  : 634)   Creating parallel br instance
  0:10:30.856     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:10:34.320     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 36526 times
  0:10:34.320     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:10:43.553     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 25360 times
  0:10:43.553     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:10:43.903     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 1153 times
  0:10:43.903     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:10:53.032     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 3697 times
  0:10:53.032     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:10:53.451     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 18718 times
  0:10:53.451     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:10:53.895     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 18211 times
  0:10:53.895     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:10:58.521     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 4198 times
  0:10:58.521     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:10:59.182     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 7 times
  0:10:59.182     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:11:00.612     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 862 times
  0:11:00.612     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:11:04.723     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 4614 times
  0:11:04.723     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:11:05.005     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 173 times
  0:11:05.005     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:11:13.075     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 374 times
  0:11:13.075     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:11:13.367     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 3554 times
  0:11:13.368     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:11:13.597     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 347 times
  0:11:13.597     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:11:17.504     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 570 times
  0:11:17.504     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:11:18.080     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:11:18.080     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:11:19.320     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 123 times
  0:11:19.320     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:11:19.587     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 103 times
  0:11:19.587     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:11:19.853     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 8 times
  0:11:19.853     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:11:27.565     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 43 times
  0:11:27.565     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:11:27.567     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 72 times
  0:11:27.567     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:11:27.568     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 8 times
  0:11:27.568     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:11:27.596     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 46 times
  0:11:27.596     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:11:27.596     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:11:27.596     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:11:28.779     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 13 times
  0:11:28.779     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:11:28.789     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 5 times
  0:11:28.789     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:11:29.054     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 1 times
  0:11:29.054     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:11:36.913     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 6 times
  0:11:36.913     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:11:36.913     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 2 times
  0:11:36.913     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:11:36.913     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 0 times
  0:11:36.913     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:11:36.916     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 3 times
  0:11:36.916     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:11:36.916     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:11:36.916     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:11:38.075     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 2 times
  0:11:38.075     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:11:38.077     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 0 times
  0:11:38.077     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:11:38.347     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 0 times
  0:11:38.347     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 0 times
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 0 times
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:11:46.169     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Relative coverage component remover
  0:11:47.250     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Relative coverage component remover triggered 0 times
  0:11:47.250     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Disconnecting edges with relatively low coverage
  0:11:47.250     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Disconnecting edges with relatively low coverage triggered 0 times
  0:11:47.250     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex tip clipper
  0:11:47.511     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex tip clipper triggered 0 times
  0:11:47.511     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Complex bulge remover
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Complex bulge remover triggered 0 times
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Tip clipper
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Tip clipper triggered 0 times
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Final tip clipper
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Final tip clipper triggered 0 times
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Bulge remover
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Bulge remover triggered 0 times
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Thorn remover (meta)
  0:11:55.379     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Thorn remover (meta) triggered 0 times
  0:11:55.379     1G / 9G    INFO    General                 (simplification.cpp        : 326)   Running Hidden EC remover (meta)
  0:11:55.684     1G / 9G    INFO    General                 (simplification.cpp        : 330)   Disrupting self-conjugate edges
  0:11:57.773     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 165)   Running Removing isolated edges
  0:11:57.968     1G / 9G    INFO   Simplification           (parallel_processing.hpp   : 167)   Removing isolated edges triggered 1237 times
  0:11:57.968     1G / 9G    INFO    General                 (simplification.cpp        : 470)   Counting average coverage
  0:11:58.784     1G / 9G    INFO    General                 (simplification.cpp        : 476)   Average coverage = 4.4643
  0:11:58.784     1G / 9G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Contig Output
  0:11:58.784     1G / 9G    INFO    General                 (contig_output_stage.cpp   :  40)   Writing GFA to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/assembly_graph_with_scaffolds.gfa
  0:12:06.634     1G / 9G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/before_rr.fasta
  0:12:15.431     1G / 9G    INFO    General                 (contig_output_stage.cpp   :  51)   Outputting FastG graph to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/assembly_graph.fastg
  0:12:38.130     1G / 9G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/simplified_contigs.fasta
  0:12:48.042     1G / 9G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/final_contigs.fasta
  0:12:56.890     1G / 9G    INFO   StageManager             (stage.cpp                 : 132)   STAGE == Contig Output
  0:12:56.890     1G / 9G    INFO    General                 (contig_output_stage.cpp   :  40)   Writing GFA to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/assembly_graph_with_scaffolds.gfa
  0:13:03.482     1G / 9G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/before_rr.fasta
  0:13:11.355     1G / 9G    INFO    General                 (contig_output_stage.cpp   :  51)   Outputting FastG graph to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/assembly_graph.fastg
  0:13:36.020     1G / 9G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/simplified_contigs.fasta
  0:13:44.922     1G / 9G    INFO    General                 (contig_output.hpp         :  22)   Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/final_contigs.fasta
  0:13:53.786     1G / 9G    INFO    General                 (launch.hpp                : 149)   SPAdes finished
  0:13:59.237    64M / 9G    INFO    General                 (main.cpp                  : 109)   Assembling time: 0 hours 13 minutes 59 seconds
Max read length detected as 151

== Running assembler: K33

  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K33/configs/config.info
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K33/configs/mda_mode.info
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  74)   Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K33/configs/meta_mode.info
  0:00:00.000     4M / 4M    INFO    General                 (memory_limit.cpp          :  49)   Memory limit set to 250 Gb
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  87)   Starting SPAdes, built from refs/heads/spades_3.13.0, git revision 8ea46659e9b2aca35444a808db550ac333006f8b
  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 (/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenome_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/dataset.info) with K=33
  0:00:00.000     4M / 4M    INFO    General                 (main.cpp                  :  90)   Maximum # of threads to use (adjusted due to OMP capabilities): 16
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  51)   SPAdes started
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  58)   Starting from stage: construction
  0:00:00.000     4M / 4M    INFO    General                 (launch.hpp                :  65)   Two-step RR enabled: 0
  0:00:00.000     4M / 4M    INFO   StageManager             (stage.cpp                 : 132)   STAGE == de Bruijn graph construction
  0:00:00.034     4M / 4M    INFO    General                 (read_converter.hpp        :  59)   Binary reads detected
  0:00:00.053     4M / 4M    INFO    General                 (construction.cpp          : 111)   Max read length 151
  0:00:00.053     4M / 4M    INFO    General                 (construction.cpp          : 117)   Average read length 146.97
  0:00:00.053     4M / 4M    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == k+1-mer counting
  0:00:00.055     4M / 4M    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:00:00.056     4M / 4M    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:00:00.056     4M / 4M    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20825 Gb
  0:00:00.056     4M / 4M    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 131072
  0:00:19.020     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 289)   Processed 9306164 reads
  0:00:37.729     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 289)   Processed 18604157 reads
  0:00:52.578     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 289)   Processed 24612210 reads
  0:00:52.578     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 295)   Adding contigs from previous K
  0:02:16.348    64M / 9G    INFO    General                 (kmer_splitters.hpp        : 308)   Used 24612210 reads
  0:02:16.348    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:02:54.632    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 438493487 kmers in total.
  0:02:54.632    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:03:31.691    64M / 9G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Extension index construction
  0:03:31.694    64M / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:03:31.694    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 117)   Splitting kmer instances into 256 files using 16 threads. This might take a while.
  0:03:31.703    64M / 9G    INFO    General                 (file_limit.hpp            :  32)   Open file limit set to 1024
  0:03:31.703    64M / 9G    INFO    General                 (kmer_splitters.hpp        :  89)   Memory available for splitting buffers: 5.20703 Gb
  0:03:31.703    64M / 9G    INFO    General                 (kmer_splitters.hpp        :  97)   Using cell size of 131072
  0:03:38.631     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 6267856 kmers
  0:03:41.457     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 12942053 kmers
  0:03:44.466     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 20483259 kmers
  0:03:48.118     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 33497956 kmers
  0:03:50.755     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 40194555 kmers
  0:03:53.995     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 47701596 kmers
  0:03:57.768     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 60908309 kmers
  0:04:00.514     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 67601493 kmers
  0:04:03.319     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 75110715 kmers
  0:04:07.135     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 88300136 kmers
  0:04:10.049     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 94993294 kmers
  0:04:12.989     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 102498146 kmers
  0:04:16.660     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 115723208 kmers
  0:04:19.422     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 122417160 kmers
  0:04:22.482     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 129930355 kmers
  0:04:26.393     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 143124657 kmers
  0:04:29.085     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 149821206 kmers
  0:04:32.131     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 157338609 kmers
  0:05:15.526     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 380)   Processed 280147784 kmers
  0:06:13.397     8G / 9G    INFO    General                 (kmer_splitters.hpp        : 385)   Used 438494255 kmers.
  0:06:14.714    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 120)   Starting k-mer counting.
  0:06:47.129    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 127)   K-mer counting done. There are 438904258 kmers in total.
  0:06:47.129    64M / 9G    INFO    General                 (kmer_index_builder.hpp    : 133)   Merging temporary buckets.
  0:07:23.901    64M / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
  0:07:46.290   264M / 9G    INFO    General                 (kmer_index_builder.hpp    : 150)   Merging final buckets.
  0:08:07.927   264M / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 336)   Index built. Total 203530896 bytes occupied (3.7098 bits per kmer).
  0:08:08.259   684M / 9G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build:  99)   Building k-mer extensions from k+1-mers
  0:08:36.814   684M / 9G    INFO   DeBruijnExtensionIndexBu (kmer_extension_index_build: 103)   Building k-mer extensions from k+1-mers finished.
  0:08:36.818   684M / 9G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Early tip clipping
  0:08:36.818   684M / 9G    INFO    General                 (construction.cpp          : 253)   Early tip clipper length bound set as (RL - K)
  0:08:36.818   684M / 9G    INFO   Early tip clipping       (early_simplification.hpp  : 181)   Early tip clipping
  0:09:34.162   676M / 9G    INFO   Early tip clipping       (early_simplification.hpp  : 184)   27315628 34-mers were removed by early tip clipper
  0:09:34.162   676M / 9G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Condensing graph
  0:09:34.204   676M / 9G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 355)   Extracting unbranching paths
  0:10:13.921   972M / 9G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 374)   Extracting unbranching paths finished. 3363133 sequences extracted
  0:10:30.888   972M / 9G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 310)   Collecting perfect loops
  0:10:41.403   972M / 9G    INFO   UnbranchingPathExtractor (debruijn_graph_constructor: 343)   Collecting perfect loops finished. 932 loops collected
  0:10:43.440     1G / 9G    INFO    General                 (stage.cpp                 : 101)   PROCEDURE == Filling coverage indices (PHM)
  0:10:43.440     1G / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 301)   Building kmer index
  0:10:43.440     1G / 9G    INFO   K-mer Index Building     (kmer_index_builder.hpp    : 314)   Building perfect hash indices
asl commented 5 years ago

Given that it is stuck in some random (and unusual) places I'd suspect some hardware issue on your end. E.g. with input/output subsystem.

jolespin commented 5 years ago

Haha, I was hoping that wasn't the case... Hmm, do you have any recommendations on parameters I can adjust that might help me get around this or potentially debug? Dependencies?

asl commented 5 years ago

You may want to check with your system administrator about the details of your hardware (e.g. data storage), etc. Maybe the system log contains some clues.

jolespin commented 5 years ago

I noticed that Debug mode is turned OFF from the spades.log. If this is turned on, will it make the log more verbose or is this for something completely different?

I suspect it has something to do w/ my conda installation. I installed a brand new version of conda on the server and I've manually installed v3.13.1.

Also, does the default memory limit of 250 gb seem reasonable for this particular run based on the total number of reads and k-mers above?

Thanks again.

asl commented 5 years ago

I noticed that Debug mode is turned OFF from the spades.log. If this is turned on, will it make the log more verbose or is this for something completely different?

No. It is for SPAdes' developers internal consumption

Also, does the default memory limit of 250 gb seem reasonable for this particular run based on the total number of reads and k-mers above?

20 Gb should be more than enough for this particular assembly, I believe.

jolespin commented 5 years ago

An interesting development, I've installed a completely new version of conda with a fresh install of metaspades v3.13.1. I ran my same command and it failed at a different stage:

spades.log

``` Command line: /usr/local/devel/ANNOTATION/jespinoz/anaconda3/envs/metagenomics_env/bin/metaspades.py -1 /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz -2 /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz -o /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output --tmp-dir /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/tmp --threads 16 --memory 250 System information: SPAdes version: 3.13.1 Python version: 2.7.15 OS: Linux-2.6.32-696.18.7.el6.x86_64-x86_64-with-centos-6.4-Final Output dir: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output Mode: read error correction and assembling Debug mode is turned OFF Dataset parameters: Metagenomic mode Reads: Library number: 1, library type: paired-end orientation: fr left reads: ['/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz'] right reads: ['/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.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: [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: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/tmp Threads: 16 Memory limit (in Gb): 250 ======= SPAdes pipeline started. Log can be found here: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/spades.log ===== Read error correction started. == Running read error correction tool: /usr/local/devel/ANNOTATION/jespinoz/anaconda3/envs/metagenomics_env/share/spades-3.13.1-0/bin/spades-hammer /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/corrected/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 75) Starting BayesHammer, built from refs/heads/spades_3.13.1, git revision 9a9d54db2ff9abaac718155bf74c12ec9464e8ca 0:00:00.000 4M / 4M INFO General (main.cpp : 76) Loading config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/corrected/configs/config.info 0:00:00.001 4M / 4M INFO General (main.cpp : 78) Maximum # of threads to use (adjusted due to OMP capabilities): 16 0:00:00.001 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 250 Gb 0:00:00.001 4M / 4M INFO General (main.cpp : 86) Trying to determine PHRED offset 0:00:00.020 4M / 4M INFO General (main.cpp : 92) Determined value is 33 0:00:00.020 4M / 4M INFO General (hammer_tools.cpp : 36) Hamming graph threshold tau=1, k=21, subkmer positions = [ 0 10 ] 0:00:00.020 4M / 4M INFO General (main.cpp : 113) Size of aux. kmer data 24 bytes === ITERATION 0 begins === 0:00:00.020 4M / 4M INFO K-mer Counting (kmer_data.cpp : 280) Estimating k-mer count 0:00:00.113 260M / 260M INFO K-mer Counting (kmer_data.cpp : 285) Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz 0:00:28.181 320M / 320M INFO K-mer Counting (kmer_data.cpp : 294) Processed 6432954 reads 0:00:28.181 320M / 320M INFO K-mer Counting (kmer_data.cpp : 285) Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz 0:00:55.827 320M / 320M INFO K-mer Counting (kmer_data.cpp : 294) Processed 12865908 reads 0:00:55.827 320M / 320M INFO K-mer Counting (kmer_data.cpp : 299) Total 12865908 reads processed 0:00:57.648 320M / 320M INFO K-mer Counting (kmer_data.cpp : 306) Estimated 1071469545 distinct kmers 0:00:57.649 64M / 320M INFO K-mer Counting (kmer_data.cpp : 311) Filtering singleton k-mers 39 8 0 nslots: 2147483648 bits per slot: 8 range: 0000008000000000 0:00:57.649 2G / 2G INFO K-mer Counting (kmer_data.cpp : 317) Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz 0:13:43.314 2G / 2G INFO K-mer Counting (kmer_data.cpp : 326) Processed 6432954 reads 0:13:43.314 2G / 2G INFO K-mer Counting (kmer_data.cpp : 317) Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz 0:22:58.138 2G / 2G INFO K-mer Counting (kmer_data.cpp : 326) Processed 12865908 reads 0:22:58.138 2G / 2G INFO K-mer Counting (kmer_data.cpp : 331) Total 12865908 reads processed 0:22:58.146 2G / 2G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:22:58.146 2G / 2G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 256 files using 16 threads. This might take a while. 0:22:58.148 2G / 2G INFO General (file_limit.hpp : 32) Open file limit set to 1024 0:22:58.148 2G / 2G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 5.15422 Gb 0:22:58.148 2G / 2G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144 0:22:59.838 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 97) Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz 0:23:33.475 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 107) Processed 4681537 reads 0:23:49.906 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 107) Processed 6432954 reads 0:23:49.906 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 97) Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz 0:24:25.520 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 107) Processed 11082008 reads 0:24:40.953 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 107) Processed 12865908 reads 0:24:40.954 11G / 11G INFO K-mer Splitting (kmer_data.cpp : 112) Total 12865908 reads processed 0:24:42.050 2G / 11G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:25:04.994 2G / 11G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 520078414 kmers in total. 0:25:04.994 2G / 11G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:25:27.031 2G / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:25:45.588 2G / 11G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:25:59.554 2G / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 241186474 bytes occupied (3.71 bits per kmer). 0:25:59.568 264M / 11G INFO K-mer Counting (kmer_data.cpp : 356) Arranging kmers in hash map order 0:26:21.069 8G / 11G INFO General (main.cpp : 148) Clustering Hamming graph. 0:34:12.229 8G / 11G INFO General (main.cpp : 155) Extracting clusters 0:36:01.545 8G / 29G INFO General (main.cpp : 167) Clustering done. Total clusters: 475169318 0:36:01.554 4G / 29G INFO K-mer Counting (kmer_data.cpp : 376) Collecting K-mer information, this takes a while. 0:36:05.539 15G / 29G INFO K-mer Counting (kmer_data.cpp : 382) Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz 0:37:25.380 15G / 29G INFO K-mer Counting (kmer_data.cpp : 382) Processing /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz 0:38:44.023 15G / 29G INFO K-mer Counting (kmer_data.cpp : 389) Collection done, postprocessing. 0:38:45.660 15G / 29G INFO K-mer Counting (kmer_data.cpp : 403) There are 520078414 kmers in total. Among them 1076972 (0.207079%) are singletons. 0:38:45.660 15G / 29G INFO General (main.cpp : 173) Subclustering Hamming graph 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 649) Subclustering done. Total 3293 non-read kmers were generated. 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 650) Subclustering statistics: 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 651) Total singleton hamming clusters: 450072774. Among them 439704340 (97.6963%) are good 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 652) Total singleton subclusters: 6381387. Among them 6381166 (99.9965%) are good 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 653) Total non-singleton subcluster centers: 25550695. Among them 25376104 (99.3167%) are good 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 654) Average size of non-trivial subcluster: 2.7401 kmers 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 655) Average number of sub-clusters per non-singleton cluster: 1.27237 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 656) Total solid k-mers: 471461610 0:39:25.539 15G / 29G INFO Hamming Subclustering (kmer_cluster.cpp : 657) Substitution probabilities: [4,4]((0.943725,0.0129303,0.0311364,0.0122081),(0.0104258,0.939102,0.0154774,0.034995),(0.0305376,0.0131951,0.943911,0.0123565),(0.0103756,0.0261745,0.0108634,0.952586)) 0:39:26.132 15G / 29G INFO General (main.cpp : 178) Finished clustering. 0:39:26.132 15G / 29G INFO General (main.cpp : 197) Starting solid k-mers expansion in 16 threads. 0:40:27.428 15G / 29G INFO General (main.cpp : 218) Solid k-mers iteration 0 produced 10945296 new k-mers. 0:41:24.184 15G / 29G INFO General (main.cpp : 218) Solid k-mers iteration 1 produced 230322 new k-mers. 0:42:21.254 15G / 29G INFO General (main.cpp : 218) Solid k-mers iteration 2 produced 6909 new k-mers. 0:43:19.658 15G / 29G INFO General (main.cpp : 218) Solid k-mers iteration 3 produced 173 new k-mers. 0:44:17.009 15G / 29G INFO General (main.cpp : 218) Solid k-mers iteration 4 produced 0 new k-mers. 0:44:17.009 15G / 29G INFO General (main.cpp : 222) Solid k-mers finalized 0:44:17.009 15G / 29G INFO General (hammer_tools.cpp : 220) Starting read correction in 16 threads. 0:44:17.009 15G / 29G INFO General (hammer_tools.cpp : 233) Correcting pair of reads: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz and /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz 0:44:27.850 17G / 29G INFO General (hammer_tools.cpp : 168) Prepared batch 0 of 1600000 reads. 0:44:46.603 17G / 29G INFO General (hammer_tools.cpp : 175) Processed batch 0 0:44:50.254 17G / 29G INFO General (hammer_tools.cpp : 185) Written batch 0 0:45:01.847 18G / 29G INFO General (hammer_tools.cpp : 168) Prepared batch 1 of 1600000 reads. 0:45:20.464 18G / 29G INFO General (hammer_tools.cpp : 175) Processed batch 1 0:45:23.669 18G / 29G INFO General (hammer_tools.cpp : 185) Written batch 1 0:45:34.150 18G / 29G INFO General (hammer_tools.cpp : 168) Prepared batch 2 of 1600000 reads. 0:45:52.818 18G / 29G INFO General (hammer_tools.cpp : 175) Processed batch 2 0:45:56.482 18G / 29G INFO General (hammer_tools.cpp : 185) Written batch 2 0:46:07.061 18G / 29G INFO General (hammer_tools.cpp : 168) Prepared batch 3 of 1600000 reads. 0:46:25.826 18G / 29G INFO General (hammer_tools.cpp : 175) Processed batch 3 0:46:29.506 18G / 29G INFO General (hammer_tools.cpp : 185) Written batch 3 0:46:30.067 18G / 29G INFO General (hammer_tools.cpp : 168) Prepared batch 4 of 32954 reads. 0:46:30.592 18G / 29G INFO General (hammer_tools.cpp : 175) Processed batch 4 0:46:30.692 18G / 29G INFO General (hammer_tools.cpp : 185) Written batch 4 0:46:36.165 15G / 29G INFO General (hammer_tools.cpp : 274) Correction done. Changed 2673607 bases in 1735725 reads. 0:46:36.165 15G / 29G INFO General (hammer_tools.cpp : 275) Failed to correct 33781 bases out of 1888692442. 0:46:36.240 64M / 29G INFO General (main.cpp : 255) Saving corrected dataset description to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/corrected/corrected.yaml 0:46:36.248 64M / 29G INFO General (main.cpp : 262) All done. Exiting. == Compressing corrected reads (with pigz) == Dataset description file was created: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/corrected/corrected.yaml ===== Read error correction finished. ===== Assembling started. == Running assembler: K21 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K21/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K21/configs/mda_mode.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K21/configs/meta_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 250 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.1, git revision 9a9d54db2ff9abaac718155bf74c12ec9464e8ca 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 (/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/dataset.info) with K=21 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 16 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: 0 0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction 0:00:00.006 4M / 4M INFO General (read_converter.hpp : 77) Converting reads to binary format for library #0 (takes a while) 0:00:00.006 4M / 4M INFO General (read_converter.hpp : 78) Converting paired reads 0:00:00.669 84M / 84M INFO General (binary_converter.hpp : 93) 16384 reads processed 0:00:01.000 100M / 100M INFO General (binary_converter.hpp : 93) 32768 reads processed 0:00:01.510 128M / 128M INFO General (binary_converter.hpp : 93) 65536 reads processed 0:00:02.497 192M / 192M INFO General (binary_converter.hpp : 93) 131072 reads processed 0:00:04.181 316M / 316M INFO General (binary_converter.hpp : 93) 262144 reads processed 0:00:07.380 564M / 564M INFO General (binary_converter.hpp : 93) 524288 reads processed 0:00:17.118 948M / 948M INFO General (binary_converter.hpp : 93) 1048576 reads processed 0:00:33.250 952M / 952M INFO General (binary_converter.hpp : 93) 2097152 reads processed 0:01:05.264 952M / 952M INFO General (binary_converter.hpp : 93) 4194304 reads processed 0:01:35.299 544M / 952M INFO General (binary_converter.hpp : 117) 6032100 reads written 0:01:35.876 4M / 952M INFO General (read_converter.hpp : 87) Converting single reads 0:01:36.058 140M / 952M INFO General (binary_converter.hpp : 93) 16384 reads processed 0:01:36.151 148M / 952M INFO General (binary_converter.hpp : 93) 32768 reads processed 0:01:36.325 160M / 952M INFO General (binary_converter.hpp : 93) 65536 reads processed 0:01:36.680 192M / 952M INFO General (binary_converter.hpp : 93) 131072 reads processed 0:01:37.628 244M / 952M INFO General (binary_converter.hpp : 117) 241905 reads written 0:01:37.749 4M / 952M INFO General (read_converter.hpp : 95) Converting merged reads 0:01:37.846 132M / 952M INFO General (binary_converter.hpp : 117) 0 reads written 0:01:38.459 4M / 952M INFO General (construction.cpp : 111) Max read length 151 0:01:38.459 4M / 952M INFO General (construction.cpp : 117) Average read length 146.97 0:01:38.459 4M / 952M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:01:38.462 4M / 952M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 256 files using 16 threads. This might take a while. 0:01:38.464 4M / 952M INFO General (file_limit.hpp : 32) Open file limit set to 1024 0:01:38.464 4M / 952M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 5.20825 Gb 0:01:38.464 4M / 952M INFO General (kmer_splitters.hpp : 97) Using cell size of 262144 0:02:01.428 8G / 9G INFO General (kmer_splitters.hpp : 289) Processed 16824210 reads 0:02:12.690 8G / 9G INFO General (kmer_splitters.hpp : 289) Processed 24612210 reads 0:02:12.690 8G / 9G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:02:14.180 64M / 9G INFO General (kmer_splitters.hpp : 308) Used 24612210 reads 0:02:14.180 64M / 9G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:02:27.072 64M / 9G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 439103884 kmers in total. 0:02:27.072 64M / 9G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:02:46.648 64M / 9G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:02:46.651 64M / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:02:46.651 64M / 9G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 256 files using 16 threads. This might take a while. 0:02:46.653 64M / 9G INFO General (file_limit.hpp : 32) Open file limit set to 1024 0:02:46.653 64M / 9G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 5.20703 Gb 0:02:46.653 64M / 9G INFO General (kmer_splitters.hpp : 97) Using cell size of 262144 0:02:51.369 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 4662698 kmers 0:02:55.513 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 31901089 kmers 0:02:59.433 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 59336276 kmers 0:03:03.489 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 86784959 kmers 0:03:07.746 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 114227892 kmers 0:03:11.991 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 141665859 kmers 0:03:16.288 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 169119197 kmers 0:03:20.291 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 196553308 kmers 0:03:24.880 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 224006554 kmers 0:03:29.104 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 251452534 kmers 0:03:33.061 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 278894562 kmers 0:03:37.529 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 306338516 kmers 0:03:41.641 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 333788643 kmers 0:03:45.593 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 361228445 kmers 0:03:49.994 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 388665161 kmers 0:03:54.185 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 416112975 kmers 0:03:58.327 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 439104140 kmers 0:03:58.327 8G / 9G INFO General (kmer_splitters.hpp : 385) Used 439104140 kmers. 0:03:59.567 64M / 9G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:04:17.936 64M / 9G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 438410056 kmers in total. 0:04:17.936 64M / 9G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:04:39.133 64M / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:04:56.150 256M / 9G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:05:07.475 256M / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 203299576 bytes occupied (3.70976 bits per kmer). 0:05:07.847 676M / 9G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:05:36.680 676M / 9G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:05:36.685 676M / 9G INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping 0:05:36.685 676M / 9G INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K) 0:05:36.685 676M / 9G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping 0:06:38.920 676M / 9G INFO Early tip clipping (early_simplification.hpp : 184) 38221328 22-mers were removed by early tip clipper 0:06:38.920 676M / 9G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:06:38.964 676M / 9G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:07:19.605 1G / 9G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 5316310 sequences extracted 0:07:35.419 1G / 9G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:07:45.869 1G / 9G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 1181 loops collected 0:07:48.937 2G / 9G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:07:48.937 2G / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:07:48.937 2G / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:08:02.521 2G / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 203641438 bytes occupied (3.71013 bits per kmer). 0:08:03.370 4G / 9G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:08:47.993 4G / 9G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:09:09.564 4G / 9G INFO General (construction.cpp : 464) Processed 10633265 edges 0:09:11.558 1G / 9G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:09:11.558 1G / 9G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:09:11.560 1G / 9G INFO General (graph_simplification.hpp : 669) Flanking coverage based disconnection disabled 0:09:11.560 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:09:12.172 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 0 times 0:09:12.172 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper 0:09:13.764 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 56328 times 0:09:13.764 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover 0:09:32.867 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 670453 times 0:09:32.867 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover 0:09:34.158 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 148366 times 0:09:34.425 1G / 9G INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:09:34.425 1G / 9G INFO General (simplification.cpp : 357) Graph simplification started 0:09:34.425 1G / 9G INFO General (graph_simplification.hpp : 641) Creating parallel br instance 0:09:34.425 1G / 9G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:09:34.425 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:09:36.598 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 139121 times 0:09:36.598 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:10:25.366 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 364778 times 0:10:25.366 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:10:25.793 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:10:25.793 1G / 9G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 2 0:10:25.793 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:10:26.215 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 8047 times 0:10:26.215 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:10:26.913 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 169 times 0:10:26.913 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:10:27.971 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 34595 times 0:10:27.971 1G / 9G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 3 0:10:27.971 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:10:28.038 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 1788 times 0:10:28.038 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:10:30.924 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 6687 times 0:10:30.924 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:10:33.441 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 81644 times 0:10:33.441 1G / 9G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 4 0:10:33.441 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:10:33.735 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2443 times 0:10:33.735 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:10:43.353 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 13709 times 0:10:43.353 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:10:43.626 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 11 times 0:10:43.626 1G / 9G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 5 0:10:43.626 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:10:43.653 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 55 times 0:10:43.653 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:10:43.664 1G / 9G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 6 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Low coverage edge remover 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Low coverage edge remover triggered 0 times 0:10:43.664 1G / 9G INFO StageManager (stage.cpp : 132) STAGE == Simplification Cleanup 0:10:43.664 1G / 9G INFO General (simplification.cpp : 196) PROCEDURE == Post simplification 0:10:43.664 1G / 9G INFO General (graph_simplification.hpp : 641) Creating parallel br instance 0:10:43.664 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:10:47.142 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 36526 times 0:10:47.142 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:10:56.911 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 25360 times 0:10:56.911 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:10:57.260 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 1153 times 0:10:57.260 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:11:06.683 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 3697 times 0:11:06.683 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:11:07.178 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 18718 times 0:11:07.178 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:11:07.736 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 18211 times 0:11:07.736 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:11:12.386 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 4198 times 0:11:12.386 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:11:13.015 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 7 times 0:11:13.015 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:11:14.568 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 862 times 0:11:14.568 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:11:18.996 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 4614 times 0:11:18.996 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:11:19.284 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 173 times 0:11:19.284 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:11:27.389 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 374 times 0:11:27.389 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:11:27.685 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 3554 times 0:11:27.685 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:11:27.930 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 347 times 0:11:27.930 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:11:32.055 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 570 times 0:11:32.055 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:11:32.613 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times 0:11:32.613 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:11:34.023 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 123 times 0:11:34.023 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:11:34.284 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 103 times 0:11:34.284 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:11:34.572 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 8 times 0:11:34.572 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:11:42.446 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 43 times 0:11:42.446 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:11:42.448 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 72 times 0:11:42.448 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:11:42.449 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 8 times 0:11:42.449 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:11:42.485 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 46 times 0:11:42.485 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:11:42.486 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times 0:11:42.486 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:11:43.642 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 13 times 0:11:43.642 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:11:43.652 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 5 times 0:11:43.652 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:11:43.918 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 1 times 0:11:43.918 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:11:51.828 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 6 times 0:11:51.828 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:11:51.829 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 2 times 0:11:51.829 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:11:51.829 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times 0:11:51.829 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:11:51.832 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 3 times 0:11:51.832 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:11:51.832 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times 0:11:51.832 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:11:53.152 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 2 times 0:11:53.152 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:11:53.154 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 0 times 0:11:53.154 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:11:53.430 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times 0:11:53.430 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 0 times 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times 0:12:01.231 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Relative coverage component remover 0:12:02.394 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Relative coverage component remover triggered 0 times 0:12:02.394 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Disconnecting edges with relatively low coverage 0:12:02.394 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Disconnecting edges with relatively low coverage triggered 0 times 0:12:02.394 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex tip clipper 0:12:02.681 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex tip clipper triggered 0 times 0:12:02.681 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Complex bulge remover 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Complex bulge remover triggered 0 times 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Tip clipper triggered 0 times 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Final tip clipper 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Final tip clipper triggered 0 times 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Bulge remover 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Bulge remover triggered 0 times 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Thorn remover (meta) 0:12:10.465 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Thorn remover (meta) triggered 0 times 0:12:10.465 1G / 9G INFO General (simplification.cpp : 326) Running Hidden EC remover (meta) 0:12:10.792 1G / 9G INFO General (simplification.cpp : 330) Disrupting self-conjugate edges 0:12:12.638 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Removing isolated edges 0:12:12.833 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Removing isolated edges triggered 1237 times 0:12:12.833 1G / 9G INFO General (simplification.cpp : 470) Counting average coverage 0:12:13.591 1G / 9G INFO General (simplification.cpp : 476) Average coverage = 4.4643 0:12:13.591 1G / 9G INFO StageManager (stage.cpp : 132) STAGE == Contig Output 0:12:13.591 1G / 9G INFO General (contig_output.hpp : 22) Outputting contigs to /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output//K21/simplified_contigs.fasta 0:12:24.640 1G / 9G INFO General (launch.hpp : 151) SPAdes finished 0:12:30.469 64M / 9G INFO General (main.cpp : 109) Assembling time: 0 hours 12 minutes 30 seconds Max read length detected as 151 == Running assembler: K33 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K33/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K33/configs/mda_mode.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K33/configs/meta_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 250 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.1, git revision 9a9d54db2ff9abaac718155bf74c12ec9464e8ca 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 (/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/dataset.info) with K=33 0:00:00.000 4M / 4M INFO General (main.cpp : 90) Maximum # of threads to use (adjusted due to OMP capabilities): 16 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: 0 0:00:00.000 4M / 4M INFO StageManager (stage.cpp : 132) STAGE == de Bruijn graph construction 0:00:00.039 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected 0:00:00.057 4M / 4M INFO General (construction.cpp : 111) Max read length 151 0:00:00.057 4M / 4M INFO General (construction.cpp : 117) Average read length 146.97 0:00:00.057 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.059 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 256 files using 16 threads. This might take a while. 0:00:00.061 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1024 0:00:00.061 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 5.20825 Gb 0:00:00.061 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 131072 0:00:35.453 8G / 9G INFO General (kmer_splitters.hpp : 289) Processed 9306164 reads 0:01:06.857 8G / 9G INFO General (kmer_splitters.hpp : 289) Processed 18604157 reads 0:01:28.247 8G / 9G INFO General (kmer_splitters.hpp : 289) Processed 24612210 reads 0:01:28.247 8G / 9G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K 0:02:57.949 64M / 9G INFO General (kmer_splitters.hpp : 308) Used 24612210 reads 0:02:57.949 64M / 9G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:03:44.061 64M / 9G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 438493487 kmers in total. 0:03:44.062 64M / 9G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:04:32.326 64M / 9G INFO General (stage.cpp : 101) PROCEDURE == Extension index construction 0:04:32.332 64M / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:04:32.332 64M / 9G INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 256 files using 16 threads. This might take a while. 0:04:32.338 64M / 9G INFO General (file_limit.hpp : 32) Open file limit set to 1024 0:04:32.338 64M / 9G INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 5.20703 Gb 0:04:32.338 64M / 9G INFO General (kmer_splitters.hpp : 97) Using cell size of 131072 0:04:39.809 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 6267856 kmers 0:04:44.499 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 12942053 kmers 0:04:48.515 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 20483259 kmers 0:04:52.732 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 33497956 kmers 0:04:56.307 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 40194555 kmers 0:05:00.578 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 47701596 kmers 0:05:04.603 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 60908309 kmers 0:05:09.076 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 67601493 kmers 0:05:12.475 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 75110715 kmers 0:05:17.668 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 88300136 kmers 0:05:21.427 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 94993294 kmers 0:05:24.876 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 102498146 kmers 0:05:29.762 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 115723208 kmers 0:05:33.085 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 122417160 kmers 0:05:36.651 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 129930355 kmers 0:05:41.486 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 143124657 kmers 0:05:44.883 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 149821206 kmers 0:05:48.517 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 157338609 kmers 0:06:38.086 8G / 9G INFO General (kmer_splitters.hpp : 380) Processed 280147784 kmers 0:07:40.664 8G / 9G INFO General (kmer_splitters.hpp : 385) Used 438494255 kmers. 0:07:42.149 64M / 9G INFO General (kmer_index_builder.hpp : 120) Starting k-mer counting. 0:08:14.402 64M / 9G INFO General (kmer_index_builder.hpp : 127) K-mer counting done. There are 438904258 kmers in total. 0:08:14.402 64M / 9G INFO General (kmer_index_builder.hpp : 133) Merging temporary buckets. 0:08:49.227 64M / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:09:10.668 264M / 9G INFO General (kmer_index_builder.hpp : 150) Merging final buckets. 0:09:36.785 264M / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 203530896 bytes occupied (3.7098 bits per kmer). 0:09:37.085 684M / 9G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 99) Building k-mer extensions from k+1-mers 0:10:08.263 684M / 9G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 103) Building k-mer extensions from k+1-mers finished. 0:10:08.268 684M / 9G INFO General (stage.cpp : 101) PROCEDURE == Early tip clipping 0:10:08.269 684M / 9G INFO General (construction.cpp : 253) Early tip clipper length bound set as (RL - K) 0:10:08.269 684M / 9G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping 0:11:08.934 676M / 9G INFO Early tip clipping (early_simplification.hpp : 184) 27315628 34-mers were removed by early tip clipper 0:11:08.934 676M / 9G INFO General (stage.cpp : 101) PROCEDURE == Condensing graph 0:11:08.975 676M / 9G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 355) Extracting unbranching paths 0:11:52.148 976M / 9G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 374) Extracting unbranching paths finished. 3363133 sequences extracted 0:12:10.857 976M / 9G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 310) Collecting perfect loops 0:12:22.779 976M / 9G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 343) Collecting perfect loops finished. 932 loops collected 0:12:25.223 1G / 9G INFO General (stage.cpp : 101) PROCEDURE == Filling coverage indices (PHM) 0:12:25.223 1G / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 301) Building kmer index 0:12:25.223 1G / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 314) Building perfect hash indices 0:12:38.535 2G / 9G INFO K-mer Index Building (kmer_index_builder.hpp : 336) Index built. Total 203338728 bytes occupied (3.70977 bits per kmer). 0:12:39.399 3G / 9G INFO General (construction.cpp : 388) Collecting k-mer coverage information from reads, this takes a while. 0:13:20.821 3G / 9G INFO General (construction.cpp : 508) Filling coverage and flanking coverage from PHM 0:13:44.264 3G / 9G INFO General (construction.cpp : 464) Processed 6727535 edges 0:13:45.529 1G / 9G INFO StageManager (stage.cpp : 132) STAGE == Raw Simplification 0:13:45.529 1G / 9G INFO General (simplification.cpp : 128) PROCEDURE == InitialCleaning 0:13:45.529 1G / 9G INFO General (graph_simplification.hpp : 669) Flanking coverage based disconnection disabled 0:13:45.529 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Self conjugate edge remover 0:13:45.808 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Self conjugate edge remover triggered 99 times 0:13:45.808 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Initial tip clipper 0:13:46.852 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Initial tip clipper triggered 48516 times 0:13:46.852 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Initial ec remover 0:13:56.551 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Initial ec remover triggered 317061 times 0:13:56.552 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Initial isolated edge remover 0:13:58.489 1G / 9G INFO Simplification (parallel_processing.hpp : 167) Initial isolated edge remover triggered 327427 times 0:13:58.622 1G / 9G INFO StageManager (stage.cpp : 132) STAGE == Simplification 0:13:58.622 1G / 9G INFO General (simplification.cpp : 357) Graph simplification started 0:13:58.622 1G / 9G INFO General (graph_simplification.hpp : 641) Creating parallel br instance 0:13:58.622 1G / 9G INFO General (simplification.cpp : 362) PROCEDURE == Simplification cycle, iteration 1 0:13:58.622 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper ======= SPAdes pipeline continued. Log can be found here: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/spades.log Restored from Command line: /usr/local/devel/ANNOTATION/jespinoz/anaconda3/envs/metagenomics_env/bin/metaspades.py -1 /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz -2 /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz -o /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output --tmp-dir /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/tmp --threads 16 --memory 250 with updated parameters: --tmp-dir /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/tmp --threads 16 --memory 250 Command line: /usr/local/devel/ANNOTATION/jespinoz/anaconda3/envs/metagenomics_env/bin/metaspades.py -1 /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz -2 /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.gz -o /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output --tmp-dir /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/tmp --threads 16 --memory 250 --tmp-dir /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/tmp --threads 16 --memory 250 System information: SPAdes version: 3.13.1 Python version: 2.7.15 OS: Linux-2.6.32-696.18.7.el6.x86_64-x86_64-with-centos-6.4-Final Output dir: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output Mode: read error correction and assembling Debug mode is turned OFF Dataset parameters: Metagenomic mode Reads: Library number: 1, library type: paired-end orientation: fr left reads: ['/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_1.fastq.gz'] right reads: ['/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/preprocessing/kneaddata_repaired_2.fastq.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: [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: /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/tmp Threads: 16 Memory limit (in Gb): 250 ===== Skipping Read error correction (already processed). ===== Assembling started. == Skipping assembler: K21 (already processed) Max read length detected as 151 == Skipping assembler: K33 (already processed) == Running assembler: K55 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K55/configs/config.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K55/configs/mda_mode.info 0:00:00.000 4M / 4M INFO General (main.cpp : 74) Loaded config from /local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/K55/configs/meta_mode.info 0:00:00.000 4M / 4M INFO General (memory_limit.cpp : 49) Memory limit set to 250 Gb 0:00:00.000 4M / 4M INFO General (main.cpp : 87) Starting SPAdes, built from refs/heads/spades_3.13.1, git revision 9a9d54db2ff9abaac718155bf74c12ec9464e8ca 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 (/local/ifs3_scratch/METAGENOMICS/jespinoz/Plastisphere/metagenomics_output/14-NT-02-bblueishsquare_S8/intermediate/metaspades_output/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): 16 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.092 4M / 4M INFO General (read_converter.hpp : 59) Binary reads detected 0:00:00.720 4M / 4M INFO General (construction.cpp : 111) Max read length 151 0:00:00.720 4M / 4M INFO General (construction.cpp : 117) Average read length 146.97 0:00:00.720 4M / 4M INFO General (stage.cpp : 101) PROCEDURE == k+1-mer counting 0:00:00.724 4M / 4M INFO General (kmer_index_builder.hpp : 117) Splitting kmer instances into 256 files using 16 threads. This might take a while. 0:00:00.726 4M / 4M INFO General (file_limit.hpp : 32) Open file limit set to 1024 0:00:00.726 4M / 4M INFO General (kmer_splitters.hpp : 89) Memory available for splitting buffers: 5.20825 Gb 0:00:00.726 4M / 4M INFO General (kmer_splitters.hpp : 97) Using cell size of 131072 0:00:20.054 8G / 9G INFO General (kmer_splitters.hpp : 289) Processed 11532263 reads 0:00:39.003 8G / 9G INFO General (kmer_splitters.hpp : 289) Processed 23052777 reads 0:00:44.538 8G / 9G INFO General (kmer_splitters.hpp : 289) Processed 24612210 reads 0:00:44.538 8G / 9G INFO General (kmer_splitters.hpp : 295) Adding contigs from previous K ```

It was stuck at 0:13:58.622 1G / 9G INFO Simplification (parallel_processing.hpp : 165) Running Tip clipper over night. I saw that there was a --restart-from last option so I canceled my grid job and ran this. Now it's working! :)

Do you have any insight on what could have caused the hang up at this stage? Do you still think it's an issue w/ my hardware? I've been using metaspades.py on several projects for several years and I've never had this issue which leads me to believe it's caused from some weird backend w/ my conda installation (hence, why I have a fresh conda install and a fresh conda environment) or, but hopefully not, my hardware. Are there any "reinstalls" of important backend tools I can try before I start asking trying to figure out if it's hardware? Hardware is pretty out of my knowledge-base so I want to try to rule out the other possibilities before I go down that road.

Could it be something with parallel_processing.hpp?

asl commented 5 years ago

So, yes, it really seems to be a problem with hardware / OS.

jolespin commented 5 years ago

Ok, that's good to know. Last question (sorry about all of the questions btw but I prefer using spades over other assemblers especially for metag), is there anything specific I can maybe ask our server maintenance people about debugging the hardware issue?

asl commented 5 years ago

Probably not... ask about memory issues, maybe, or something otherwise suspicious.

jolespin commented 5 years ago

I've figured it out and fixed the issue.

I was calling metaspades.py with Python's subprocess module:

import subprocess
process = subprocess.Popen("metaspades command", stdout=subprocess.PIPE, stderr=subprocess.PIPE)
process.wait()

This would lead to something called a zombie process were spades-core was defunct and it wasn't erroring or continuing.

This fix was to do the following:

import subprocess
process = subprocess.Popen("metaspades command", stdout=subprocess.PIPE, stderr=subprocess.PIPE)
stdout, stderr = process.communicate()

I just figured this out yesterday evening and was going to close this issue. Just wanted to post the solution here. I had to do lot of conda migrations to figure out what the issue could have been.

asl commented 5 years ago

That's quite strange... Is there some daemon that kills zombie processes? Because otherwise it would be defunct just from beginning and not somewhere in the middle of the computation process..

vphan13 commented 5 years ago

I believe this is documented in python's docs and discussed in the stackoverflow thread below

https://stackoverflow.com/questions/1445627/how-can-i-find-out-why-subprocess-popen-wait-waits-forever-if-stdout-pipe

In jolespin's case, the symptoms looked like iowait, but it was actually the deadlock we were seeing. An strace of the parent process is what led us to the subprocess stalling.