asl
commented
7 years ago Will you please provide us the spades.log file?
Closed guokai8 closed 7 years ago
asl
commented
7 years ago Will you please provide us the spades.log file?
guokai8
commented
7 years ago I paste the log file below
Command line: /home/data1/spades/bin/spades.py -t 80 --memory 850 -1 /dat1/Rose_Denovo/resf/girose1_R1.clean.fq -2 /dat1/Rose_Denovo/resf/girose1_R2.clean.fq --pacbio /dat1/Rose_Denovo/m54061_170321_090037.subreads.bam.fastq -o /dat1/Rose_Denovo/resf/spade/ass4
System information:
SPAdes version: 3.10.1
Python version: 2.7.5
OS: Linux-3.10.0-514.6.1.el7.x86_64-x86_64-with-centos-7.3.1611-Core
Output dir: /dat1/Rose_Denovo/resf/spade/ass4
Mode: read error correction and assembling
Debug mode is turned OFF
Dataset parameters:
Multi-cell mode (you should set '--sc' flag if input data was obtained with MDA (single-cell) technology or --meta flag if processing metagenomic dataset)
Reads:
Library number: 1, library type: paired-end
orientation: fr
left reads: ['/dat1/Rose_Denovo/resf/girose1_R1.clean.fq']
right reads: ['/dat1/Rose_Denovo/resf/girose1_R2.clean.fq']
interlaced reads: not specified
single reads: not specified
Library number: 2, library type: pacbio
left reads: not specified
right reads: not specified
interlaced reads: not specified
single reads: ['/dat1/Rose_Denovo/m54061_170321_090037.subreads.bam.fastq']
Read error correction parameters:
Iterations: 1
PHRED offset will be auto-detected
Corrected reads will be compressed (with gzip)
Assembly parameters:
k: automatic selection based on read length
Repeat resolution is enabled
Mismatch careful mode is turned OFF
MismatchCorrector will be SKIPPED
Coverage cutoff is turned OFF
Other parameters:
Dir for temp files: /dat1/Rose_Denovo/resf/spade/ass4/tmp
Threads: 80
Memory limit (in Gb): 850
======= SPAdes pipeline started. Log can be found here: /dat1/Rose_Denovo/resf/spade/ass4/spades.log
===== Read error correction started.
== Running read error correction tool: /home/data1/spades/bin/hammer /dat1/Rose_Denovo/resf/spade/ass4/corrected/configs/config.info
0:00:00.000 4M / 4M INFO General (main.cpp : 83) Starting BayesHammer, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 84) Loading config from /dat1/Rose_Denovo/resf/spade/ass4/corrected/configs/config.info
0:00:00.002 4M / 4M INFO General (memory_limit.hpp : 47) Memory limit set to 850 Gb
0:00:00.002 4M / 4M INFO General (main.cpp : 93) Trying to determine PHRED offset
0:00:00.002 4M / 4M INFO General (main.cpp : 99) 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 : 120) Size of aux. kmer data 24 bytes
=== ITERATION 0 begins ===
0:00:00.003 4M / 4M INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
0:00:00.003 4M / 4M INFO K-mer Splitting (kmer_data.cpp : 91) Splitting kmer instances into 1280 buckets. This might take a while.
0:00:00.004 4M / 4M INFO General (file_limit.hpp : 30) Open file limit set to 102400
0:00:00.004 4M / 4M INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.54165 Gb
0:00:00.004 4M / 4M INFO General (kmer_index_builder.hpp : 116) Using cell size of 52428
0:00:07.489 44G / 44G INFO K-mer Splitting (kmer_data.cpp : 98) Processing /dat1/Rose_Denovo/resf/girose1_R1.clean.fq
0:02:09.998 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 16476269 reads
0:04:08.972 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 33353032 reads
0:06:08.180 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 50169627 reads
0:08:07.715 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 66904716 reads
0:10:06.182 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 83429326 reads
0:11:59.640 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 99547766 reads
0:13:56.317 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 115940690 reads
0:15:55.021 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 132519237 reads
0:17:52.917 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 148494489 reads
0:19:57.762 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 165217882 reads
0:22:05.897 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 182129007 reads
0:24:06.094 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 198231754 reads
0:26:09.368 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 214645391 reads
0:34:02.551 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 281318327 reads
0:35:51.586 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 98) Processing /dat1/Rose_Denovo/resf/girose1_R2.clean.fq
1:07:48.907 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 108) Processed 553157144 reads
1:12:52.635 44G / 46G INFO K-mer Splitting (kmer_data.cpp : 113) Total 590824020 reads processed
1:12:57.185 324M / 46G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
1:18:04.705 324M / 46G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 3834850610 kmers in total.
1:18:04.706 324M / 46G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
1:23:22.758 324M / 46G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
1:26:45.873 1G / 95G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
1:31:57.726 1G / 95G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 1252917728 bytes occupied (2.61375 bits per kmer).
1:31:57.739 1G / 95G INFO K-mer Counting (kmer_data.cpp : 359) Arranging kmers in hash map order
1:34:33.463 58G / 95G INFO General (main.cpp : 155) Clustering Hamming graph.
2:06:43.308 58G / 95G INFO General (main.cpp : 162) Extracting clusters
3:02:13.666 58G / 123G INFO General (main.cpp : 174) Clustering done. Total clusters: 957871146
3:02:13.764 30G / 123G INFO K-mer Counting (kmer_data.cpp : 381) Collecting K-mer information, this takes a while.
3:03:16.798 115G / 123G INFO K-mer Counting (kmer_data.cpp : 387) Processing /dat1/Rose_Denovo/resf/girose1_R1.clean.fq
3:26:53.222 115G / 123G INFO K-mer Counting (kmer_data.cpp : 387) Processing /dat1/Rose_Denovo/resf/girose1_R2.clean.fq
3:49:42.562 115G / 123G INFO K-mer Counting (kmer_data.cpp : 394) Collection done, postprocessing.
3:50:07.025 115G / 123G INFO K-mer Counting (kmer_data.cpp : 408) There are 3834850610 kmers in total. Among them 2660803024 (69.3848%) are singletons.
3:50:07.026 115G / 123G INFO General (main.cpp : 180) Subclustering Hamming graph
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 649) Subclustering done. Total 586871 non-read kmers were generated.
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 650) Subclustering statistics:
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 651) Total singleton hamming clusters: 620380542. Among them 260312482 (41.9601%) are good
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 652) Total singleton subclusters: 25312501. Among them 24686038 (97.5251%) are good
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 653) Total non-singleton subcluster centers: 493901360. Among them 414243509 (83.8717%) are good
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 654) Average size of non-trivial subcluster: 6.51088 kmers
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 655) Average number of sub-clusters per non-singleton cluster: 1.53845
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 656) Total solid k-mers: 699242029
4:41:09.701 115G / 123G INFO Hamming Subclustering (kmer_cluster.cpp : 657) Substitution probabilities: [4,4]((0.904209,0.0379498,0.0310598,0.0267815),(0.0348048,0.906576,0.0208388,0.0377803),(0.0366827,0.0204375,0.907209,0.0356711),(0.0262999,0.0310742,0.0379198,0.904706))
4:41:13.206 115G / 123G INFO General (main.cpp : 185) Finished clustering.
4:41:13.206 115G / 123G INFO General (main.cpp : 204) Starting solid k-mers expansion in 80 threads.
5:13:44.999 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 0 produced 460763768 new k-mers.
5:45:31.327 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 1 produced 21356995 new k-mers.
6:15:52.904 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 2 produced 1330706 new k-mers.
6:45:11.243 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 3 produced 143745 new k-mers.
7:14:24.164 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 4 produced 25083 new k-mers.
7:43:47.707 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 5 produced 7575 new k-mers.
8:13:05.946 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 6 produced 2480 new k-mers.
8:42:04.786 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 7 produced 350 new k-mers.
9:10:59.768 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 8 produced 80 new k-mers.
9:39:56.676 115G / 123G INFO General (main.cpp : 225) Solid k-mers iteration 9 produced 0 new k-mers.
9:39:56.676 115G / 123G INFO General (main.cpp : 229) Solid k-mers finalized
9:39:56.676 115G / 123G INFO General (hammer_tools.cpp : 211) Starting read correction in 80 threads.
9:39:56.676 115G / 123G INFO General (hammer_tools.cpp : 222) Correcting pair of reads: /dat1/Rose_Denovo/resf/girose1_R1.clean.fq and /dat1/Rose_Denovo/resf/girose1_R2.clean.fq
9:40:22.474 123G / 123G INFO General (hammer_tools.cpp : 166) Prepared batch 0 of 8000000 reads.
9:41:02.947 124G / 124G INFO General (hammer_tools.cpp : 175) Processed batch 0
9:41:19.924 124G / 124G INFO General (hammer_tools.cpp : 185) Written batch 0
9:41:43.935 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 1 of 8000000 reads.
9:42:21.754 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 1
9:43:05.867 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 1
9:43:28.091 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 2 of 8000000 reads.
9:44:07.701 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 2
9:44:32.068 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 2
9:44:56.332 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 3 of 8000000 reads.
9:45:34.661 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 3
9:46:13.423 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 3
9:46:34.131 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 4 of 8000000 reads.
9:47:12.886 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 4
9:48:16.580 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 4
9:48:36.876 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 5 of 8000000 reads.
9:49:16.031 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 5
9:49:40.019 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 5
9:50:00.982 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 6 of 8000000 reads.
9:50:42.093 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 6
9:51:43.418 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 6
9:52:07.011 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 7 of 8000000 reads.
9:52:43.598 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 7
9:53:01.266 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 7
9:53:24.959 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 8 of 8000000 reads.
9:54:02.263 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 8
9:54:39.942 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 8
9:55:02.914 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 9 of 8000000 reads.
9:55:46.543 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 9
9:56:12.350 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 9
9:56:35.335 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 10 of 8000000 reads.
9:57:13.736 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 10
9:57:45.332 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 10
9:58:08.046 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 11 of 8000000 reads.
9:58:48.306 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 11
9:59:57.045 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 11
10:00:19.488 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 12 of 8000000 reads.
10:00:57.354 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 12
10:02:01.194 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 12
10:02:22.139 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 13 of 8000000 reads.
10:02:59.428 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 13
10:03:48.864 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 13
10:04:11.041 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 14 of 8000000 reads.
10:04:49.423 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 14
10:05:06.892 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 14
10:05:30.718 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 15 of 8000000 reads.
10:06:07.270 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 15
10:06:34.542 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 15
10:06:58.873 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 16 of 8000000 reads.
10:07:37.487 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 16
10:08:05.667 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 16
10:08:27.127 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 17 of 8000000 reads.
10:09:04.641 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 17
10:09:40.242 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 17
10:10:01.446 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 18 of 8000000 reads.
10:10:41.957 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 18
10:11:00.233 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 18
10:11:24.487 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 19 of 8000000 reads.
10:12:04.315 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 19
10:13:05.327 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 19
10:13:27.887 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 20 of 8000000 reads.
10:14:17.538 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 20
10:14:35.706 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 20
10:14:56.657 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 21 of 8000000 reads.
10:15:49.356 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 21
10:16:17.387 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 21
10:16:40.137 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 22 of 8000000 reads.
10:17:19.790 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 22
10:17:50.637 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 22
10:18:12.608 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 23 of 8000000 reads.
10:18:53.788 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 23
10:19:59.033 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 23
10:20:21.530 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 24 of 8000000 reads.
10:21:04.476 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 24
10:21:26.474 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 24
10:21:48.726 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 25 of 8000000 reads.
10:22:32.984 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 25
10:23:08.927 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 25
10:23:31.234 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 26 of 8000000 reads.
10:24:13.989 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 26
10:24:30.571 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 26
10:24:51.843 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 27 of 8000000 reads.
10:25:39.034 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 27
10:26:05.180 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 27
10:26:28.668 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 28 of 8000000 reads.
10:27:08.837 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 28
10:27:41.818 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 28
10:28:02.334 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 29 of 8000000 reads.
10:28:45.251 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 29
10:29:03.138 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 29
10:29:26.141 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 30 of 8000000 reads.
10:30:07.770 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 30
10:30:42.757 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 30
10:31:05.554 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 31 of 8000000 reads.
10:31:42.683 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 31
10:32:54.165 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 31
10:33:18.653 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 32 of 8000000 reads.
10:33:57.323 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 32
10:34:14.771 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 32
10:34:35.185 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 33 of 8000000 reads.
10:35:12.477 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 33
10:35:48.459 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 33
10:36:08.792 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 34 of 8000000 reads.
10:36:49.065 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 34
10:37:45.160 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 34
10:38:08.011 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 35 of 8000000 reads.
10:38:44.812 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 35
10:39:51.710 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 35
10:40:14.022 125G / 125G INFO General (hammer_tools.cpp : 166) Prepared batch 36 of 7412010 reads.
10:40:47.551 125G / 125G INFO General (hammer_tools.cpp : 175) Processed batch 36
10:41:42.496 125G / 125G INFO General (hammer_tools.cpp : 185) Written batch 36
10:41:59.123 115G / 125G INFO General (hammer_tools.cpp : 270) Correction done. Changed 85323918 bases in 56680709 reads.
10:41:59.123 115G / 125G INFO General (hammer_tools.cpp : 271) Failed to correct 190042 bases out of 86969036040.
10:42:00.041 320M / 125G INFO General (main.cpp : 262) Saving corrected dataset description to /dat1/Rose_Denovo/resf/spade/ass4/corrected/corrected.yaml
10:42:00.045 320M / 125G INFO General (main.cpp : 269) All done. Exiting.
== Compressing corrected reads (with gzip)
== Dataset description file was created: /dat1/Rose_Denovo/resf/spade/ass4/corrected/corrected.yaml
===== Read error correction finished.
===== Assembling started.
== Running assembler: K21
0:00:00.000 4M / 4M INFO General (main.cpp : 75) Loading config from /dat1/Rose_Denovo/resf/spade/ass4/K21/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.hpp : 47) Memory limit set to 850 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Assembling dataset (/dat1/Rose_Denovo/resf/spade/ass4/dataset.info) with K=21
0:00:00.000 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 : 61) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 126) STAGE == Construction
0:00:00.003 4M / 4M INFO General (read_converter.hpp : 84) Converting reads to binary format for library #0 (takes a while)
0:00:00.003 4M / 4M INFO General (read_converter.hpp : 85) Converting paired reads
0:00:06.917 84M / 84M INFO General (binary_converter.hpp : 139) 16384 reads processed
0:00:07.052 96M / 96M INFO General (binary_converter.hpp : 139) 32768 reads processed
0:00:07.315 128M / 128M INFO General (binary_converter.hpp : 139) 65536 reads processed
0:00:07.836 184M / 184M INFO General (binary_converter.hpp : 139) 131072 reads processed
0:00:08.859 304M / 304M INFO General (binary_converter.hpp : 139) 262144 reads processed
0:00:10.952 548M / 548M INFO General (binary_converter.hpp : 139) 524288 reads processed
0:00:16.259 928M / 928M INFO General (binary_converter.hpp : 139) 1048576 reads processed
0:00:25.314 948M / 948M INFO General (binary_converter.hpp : 139) 2097152 reads processed
0:00:43.731 984M / 996M INFO General (binary_converter.hpp : 139) 4194304 reads processed
0:01:24.104 980M / 996M INFO General (binary_converter.hpp : 139) 8388608 reads processed
0:02:44.607 992M / 996M INFO General (binary_converter.hpp : 139) 16777216 reads processed
0:05:28.082 1004M / 1G INFO General (binary_converter.hpp : 139) 33554432 reads processed
0:11:11.504 984M / 1G INFO General (binary_converter.hpp : 139) 67108864 reads processed
0:22:30.948 976M / 1G INFO General (binary_converter.hpp : 139) 134217728 reads processed
0:45:22.831 1008M / 1G INFO General (binary_converter.hpp : 139) 268435456 reads processed
0:50:01.501 976M / 1G INFO General (binary_converter.hpp : 159) 295374451 reads written
0:50:03.193 8M / 1G INFO General (read_converter.hpp : 94) Converting single reads
0:50:03.430 140M / 1G INFO General (binary_converter.hpp : 139) 16384 reads processed
0:50:03.512 148M / 1G INFO General (binary_converter.hpp : 139) 32768 reads processed
0:50:03.600 148M / 1G INFO General (binary_converter.hpp : 159) 37253 reads written
0:50:06.392 8M / 1G INFO General (graph_construction.hpp : 120) Constructing DeBruijn graph for k=21
0:50:06.393 8M / 1G INFO General (kmer_splitters.hpp : 129) Splitting kmer instances into 6400 buckets. This might take a while.
0:50:06.396 4M / 1G INFO General (file_limit.hpp : 30) Open file limit set to 102400
0:50:06.396 4M / 1G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.54165 Gb
0:50:06.396 4M / 1G INFO General (kmer_index_builder.hpp : 116) Using cell size of 16384
0:51:22.923 70G / 70G INFO General (kmer_splitters.hpp : 153) Processed 50412969 reads
0:52:21.630 70G / 70G INFO General (kmer_splitters.hpp : 153) Processed 102061435 reads
0:53:18.987 70G / 70G INFO General (kmer_splitters.hpp : 153) Processed 153286056 reads
0:54:17.378 70G / 70G INFO General (kmer_splitters.hpp : 153) Processed 205156281 reads
0:55:16.359 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 257963006 reads
0:56:16.000 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 311533511 reads
0:57:15.557 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 361960176 reads
0:58:15.556 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 413389309 reads
0:59:15.731 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 464836832 reads
1:00:14.773 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 516425993 reads
1:01:14.755 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 569290087 reads
1:02:14.884 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 622216972 reads
1:03:19.278 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 675613583 reads
1:04:21.482 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 728385595 reads
1:05:22.257 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 781101137 reads
1:11:26.227 70G / 71G INFO General (kmer_splitters.hpp : 153) Processed 1097649497 reads
1:13:15.633 70G / 71G INFO General (kmer_splitters.hpp : 159) Adding contigs from previous K
1:13:23.332 356M / 71G INFO General (kmer_splitters.hpp : 172) Used 1181572310 reads. Maximum read length 150
1:13:23.332 356M / 71G INFO General (kmer_splitters.hpp : 173) Average read length 147.202
1:13:23.332 356M / 71G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
1:14:53.940 356M / 71G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 898773629 kmers in total.
1:14:53.941 356M / 71G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
1:16:15.663 356M / 71G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
1:16:15.663 356M / 71G INFO General (kmer_splitters.hpp : 285) Splitting kmer instances into 1280 buckets. This might take a while.
1:16:15.664 356M / 71G INFO General (file_limit.hpp : 30) Open file limit set to 102400
1:16:15.664 356M / 71G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.54022 Gb
1:16:15.664 356M / 71G INFO General (kmer_index_builder.hpp : 116) Using cell size of 52428
1:17:46.725 44G / 71G INFO General (kmer_splitters.hpp : 304) Processed 898773629 kmers
1:17:46.726 44G / 71G INFO General (kmer_splitters.hpp : 309) Used 898773629 kmers.
1:17:49.816 364M / 71G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
1:18:52.520 364M / 71G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 862516838 kmers in total.
1:18:52.520 364M / 71G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
1:20:04.569 364M / 71G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
1:21:00.959 620M / 71G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
1:22:07.495 620M / 71G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 281800552 bytes occupied (2.61375 bits per kmer).
1:22:08.325 1G / 71G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 85) Building k-mer extensions from k+1-mers
1:22:35.705 1G / 71G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 89) Building k-mer extensions from k+1-mers finished.
1:22:35.768 1G / 71G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping
1:24:11.844 1G / 71G INFO Early tip clipping (early_simplification.hpp : 184) 96855751 22-mers were removed by early tip clipper
1:24:11.844 1G / 71G INFO General (graph_construction.hpp : 136) Condensing graph
1:24:11.844 1G / 71G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 340) Extracting unbranching paths
1:35:10.168 16G / 71G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths finished. 179290666 sequences extracted
1:35:33.236 16G / 71G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 313) Collecting perfect loops
1:41:15.235 16G / 71G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 329) Collecting perfect loops finished. 1582 loops collected
1:42:28.671 34G / 71G INFO General (graph_construction.hpp : 141) Building index with from graph
1:42:28.675 34G / 71G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
1:42:28.675 34G / 71G INFO General (kmer_splitters.hpp : 214) Splitting kmer instances into 16 buckets. This might take a while.
1:42:28.675 34G / 71G INFO General (file_limit.hpp : 30) Open file limit set to 102400
1:42:28.675 34G / 71G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 271.914 Gb
1:42:28.675 34G / 71G INFO General (kmer_index_builder.hpp : 116) Using cell size of 4194304
1:42:45.016 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 9970817 edges
1:43:01.488 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 20375099 edges
1:43:18.734 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 31066313 edges
1:43:36.376 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 41952668 edges
1:43:54.046 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 52938933 edges
1:44:11.633 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 63997050 edges
1:44:33.083 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 75107948 edges
1:44:53.326 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 86267906 edges
1:45:15.914 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 97446524 edges
1:45:34.028 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 108643586 edges
1:45:52.182 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 119816438 edges
1:46:09.579 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 130998791 edges
1:46:26.830 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 142210134 edges
1:46:44.022 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 153427057 edges
1:47:00.550 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 164638036 edges
1:47:18.622 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 175856343 edges
1:47:24.079 34G / 71G INFO General (kmer_splitters.hpp : 225) Processed 179292264 edges
1:47:24.080 34G / 71G INFO General (kmer_splitters.hpp : 230) Used 179292264 sequences.
1:47:24.172 34G / 71G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
1:50:03.695 34G / 71G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 801917878 kmers in total.
1:50:03.695 34G / 71G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
1:51:07.988 34G / 71G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
1:58:06.720 34G / 71G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
1:59:10.506 34G / 71G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 262001720 bytes occupied (2.61375 bits per kmer).
1:59:21.513 52G / 71G INFO General (edge_index_builders.hpp : 27) Collecting k-mer coverage information from graph, this takes a while.
1:59:51.745 52G / 71G INFO General (edge_index.hpp : 91) Index refilled
1:59:57.424 51G / 71G INFO General (graph_construction.hpp : 173) Filling coverage index
1:59:57.424 51G / 71G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from reads, this takes a while.
2:26:26.283 51G / 71G INFO General (graph_construction.hpp : 175) Filling coverage and flanking coverage from index
2:35:41.382 51G / 71G INFO General (construction.cpp : 30) Figured out: read length = 150
2:35:41.407 51G / 71G INFO StageManager (stage.cpp : 126) STAGE == EC Threshold Finding
2:36:43.661 51G / 71G INFO General (kmer_coverage_model.cpp : 182) Kmer coverage valley at: 25
2:36:43.721 51G / 71G INFO General (kmer_coverage_model.cpp : 202) K-mer histogram maximum: 136
2:36:43.721 51G / 71G INFO General (kmer_coverage_model.cpp : 238) Estimated median coverage: 136. Coverage mad: 42.9954
2:36:43.757 51G / 71G INFO General (kmer_coverage_model.cpp : 260) Fitting coverage model
2:36:44.231 51G / 71G INFO General (kmer_coverage_model.cpp : 296) ... iteration 2
2:36:45.097 51G / 71G INFO General (kmer_coverage_model.cpp : 296) ... iteration 4
2:36:48.082 51G / 71G INFO General (kmer_coverage_model.cpp : 296) ... iteration 8
2:36:54.643 51G / 71G INFO General (kmer_coverage_model.cpp : 296) ... iteration 16
2:37:00.496 51G / 71G INFO General (kmer_coverage_model.cpp : 310) Fitted mean coverage: 107.566. Fitted coverage std. dev: 42.3375
2:37:00.503 51G / 71G INFO General (kmer_coverage_model.cpp : 335) Probability of erroneous kmer at valley: 0.0326773
2:37:00.503 51G / 71G INFO General (kmer_coverage_model.cpp : 359) Preliminary threshold calculated as: 25
2:37:00.503 51G / 71G INFO General (kmer_coverage_model.cpp : 363) Threshold adjusted to: 25
2:37:00.503 51G / 71G INFO General (kmer_coverage_model.cpp : 376) Estimated genome size (ignoring repeats): 368557672
2:37:00.527 51G / 71G INFO General (genomic_info_filler.cpp : 133) Mean coverage was calculated as 107.566
2:37:00.542 51G / 71G INFO General (genomic_info_filler.cpp : 147) EC coverage threshold value was calculated as 25
2:37:00.542 51G / 71G INFO General (genomic_info_filler.cpp : 148) Trusted kmer low bound: 0
2:37:00.542 51G / 71G INFO StageManager (stage.cpp : 126) STAGE == Simplification
2:37:04.243 33G / 71G INFO General (simplification.cpp : 380) Graph simplification started
2:37:04.243 33G / 71G INFO General (simplification.cpp : 76) PROCEDURE == InitialCleaning
2:37:04.244 33G / 71G INFO General (graph_simplification.hpp : 645) Flanking coverage based disconnection disabled
2:37:04.244 33G / 71G INFO General (simplification.cpp : 349) Running Self conjugate edge remover
2:37:13.094 33G / 71G INFO General (simplification.cpp : 351) Triggered 0 times
2:37:13.096 33G / 71G INFO General (simplification.cpp : 349) Running Initial isolated edge remover
2:37:27.572 33G / 71G INFO General (simplification.cpp : 351) Triggered 308175 times
2:37:27.572 33G / 71G INFO General (simplification.cpp : 349) Running Initial tip clipper
2:37:44.856 33G / 71G INFO General (simplification.cpp : 351) Triggered 175802 times
2:37:44.856 33G / 71G INFO General (simplification.cpp : 349) Running Initial ec remover
3:09:13.170 35G / 71G INFO General (simplification.cpp : 351) Triggered 21941287 times
3:09:56.517 34G / 71G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
3:09:56.517 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 1
3:09:56.517 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:10:04.896 34G / 71G INFO General (simplification.cpp : 351) Triggered 134815 times
3:10:04.896 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:40:14.243 34G / 71G INFO General (simplification.cpp : 351) Triggered 3954891 times
3:40:14.243 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:42:10.848 34G / 71G INFO General (simplification.cpp : 351) Triggered 869710 times
3:42:10.849 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 2
3:42:10.849 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:42:29.075 34G / 71G INFO General (simplification.cpp : 351) Triggered 11007 times
3:42:29.076 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:44:00.174 34G / 71G INFO General (simplification.cpp : 351) Triggered 137195 times
3:44:00.175 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:46:15.643 34G / 71G INFO General (simplification.cpp : 351) Triggered 1807605 times
3:46:15.643 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 3
3:46:15.643 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:46:19.687 34G / 71G INFO General (simplification.cpp : 351) Triggered 1282 times
3:46:19.687 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:49:19.981 34G / 71G INFO General (simplification.cpp : 351) Triggered 258595 times
3:49:19.981 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:49:48.199 34G / 71G INFO General (simplification.cpp : 351) Triggered 404175 times
3:49:48.199 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 4
3:49:48.199 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:49:51.135 34G / 71G INFO General (simplification.cpp : 351) Triggered 78 times
3:49:51.135 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:50:42.364 34G / 71G INFO General (simplification.cpp : 351) Triggered 71313 times
3:50:42.365 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:50:54.660 34G / 71G INFO General (simplification.cpp : 351) Triggered 199635 times
3:50:54.660 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 5
3:50:54.660 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:50:55.798 34G / 71G INFO General (simplification.cpp : 351) Triggered 33 times
3:50:55.798 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:51:22.630 34G / 71G INFO General (simplification.cpp : 351) Triggered 37472 times
3:51:22.631 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:51:29.665 34G / 71G INFO General (simplification.cpp : 351) Triggered 95598 times
3:51:29.665 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 6
3:51:29.665 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:51:30.372 34G / 71G INFO General (simplification.cpp : 351) Triggered 8 times
3:51:30.372 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:51:46.173 34G / 71G INFO General (simplification.cpp : 351) Triggered 19570 times
3:51:46.174 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:51:51.226 34G / 71G INFO General (simplification.cpp : 351) Triggered 66775 times
3:51:51.226 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 7
3:51:51.226 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:51:51.636 34G / 71G INFO General (simplification.cpp : 351) Triggered 10 times
3:51:51.636 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:52:03.252 34G / 71G INFO General (simplification.cpp : 351) Triggered 13558 times
3:52:03.253 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:52:05.966 34G / 71G INFO General (simplification.cpp : 351) Triggered 42003 times
3:52:05.966 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 8
3:52:05.966 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:52:06.224 34G / 71G INFO General (simplification.cpp : 351) Triggered 4 times
3:52:06.224 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:52:13.051 34G / 71G INFO General (simplification.cpp : 351) Triggered 8555 times
3:52:13.051 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:52:15.295 34G / 71G INFO General (simplification.cpp : 351) Triggered 35886 times
3:52:15.295 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 9
3:52:15.295 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:52:15.476 34G / 71G INFO General (simplification.cpp : 351) Triggered 7 times
3:52:15.476 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:52:20.740 34G / 71G INFO General (simplification.cpp : 351) Triggered 6674 times
3:52:20.740 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:52:22.451 34G / 71G INFO General (simplification.cpp : 351) Triggered 27383 times
3:52:22.451 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 10
3:52:22.451 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:52:22.609 34G / 71G INFO General (simplification.cpp : 351) Triggered 5 times
3:52:22.609 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:52:27.123 34G / 71G INFO General (simplification.cpp : 351) Triggered 4735 times
3:52:27.123 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:52:29.142 34G / 71G INFO General (simplification.cpp : 351) Triggered 27962 times
3:52:29.142 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 11
3:52:29.142 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:52:29.272 34G / 71G INFO General (simplification.cpp : 351) Triggered 1 times
3:52:29.272 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:52:33.464 34G / 71G INFO General (simplification.cpp : 351) Triggered 4237 times
3:52:33.464 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:52:33.464 34G / 71G INFO General (simplification.cpp : 351) Triggered 0 times
3:52:33.465 34G / 71G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 12
3:52:33.465 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:52:33.526 34G / 71G INFO General (simplification.cpp : 351) Triggered 0 times
3:52:33.526 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:52:33.527 34G / 71G INFO General (simplification.cpp : 351) Triggered 0 times
3:52:33.528 34G / 71G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:52:33.528 34G / 71G INFO General (simplification.cpp : 351) Triggered 0 times
3:52:33.528 34G / 71G INFO General (simplification.cpp : 162) PROCEDURE == Post simplification
3:52:33.528 34G / 71G INFO General (graph_simplification.hpp : 446) Disconnection of relatively low covered edges disabled
3:52:33.529 34G / 71G INFO General (graph_simplification.hpp : 476) Complex tip clipping disabled
3:52:33.529 34G / 71G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
3:52:33.529 34G / 71G INFO General (simplification.cpp : 294) Iteration 0
3:52:33.529 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:52:37.775 34G / 71G INFO General (simplification.cpp : 351) Triggered 169 times
3:52:37.775 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:56:46.489 34G / 71G INFO General (simplification.cpp : 351) Triggered 19402 times
3:56:46.490 34G / 71G INFO General (simplification.cpp : 294) Iteration 1
3:56:46.490 34G / 71G INFO General (simplification.cpp : 349) Running Tip clipper
3:56:46.739 34G / 71G INFO General (simplification.cpp : 351) Triggered 0 times
3:56:46.739 34G / 71G INFO General (simplification.cpp : 349) Running Bulge remover
3:56:46.740 34G / 71G INFO General (simplification.cpp : 351) Triggered 0 times
3:56:46.740 34G / 71G INFO General (simplification.cpp : 326) Disrupting self-conjugate edges
3:57:41.876 34G / 71G INFO StageManager (stage.cpp : 126) STAGE == Simplification Cleanup
3:57:45.057 34G / 71G INFO General (simplification.cpp : 561) Counting average coverage
3:57:57.625 34G / 71G INFO General (simplification.cpp : 566) Average coverage = 225.675
3:57:57.625 34G / 71G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
3:57:57.625 34G / 71G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K21/before_rr.fasta
4:00:11.187 34G / 71G INFO General (contig_output.hpp : 518) Outputting graph to /dat1/Rose_Denovo/resf/spade/ass4//K21/assembly_graph.fastg
4:07:48.965 34G / 71G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K21/simplified_contigs.fasta
4:09:41.610 34G / 71G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K21/final_contigs.fasta
4:11:33.541 34G / 71G INFO General (launch.hpp : 136) SPAdes finished
4:13:43.995 320M / 71G INFO General (main.cpp : 109) Assembling time: 4 hours 13 minutes 44 seconds
Default k-mer sizes were set to [21, 33, 55, 77] because estimated read length (150) is equal to or greater than 150
== Running assembler: K33
0:00:00.000 4M / 4M INFO General (main.cpp : 75) Loading config from /dat1/Rose_Denovo/resf/spade/ass4/K33/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.hpp : 47) Memory limit set to 850 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Assembling dataset (/dat1/Rose_Denovo/resf/spade/ass4/dataset.info) with K=33
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 : 61) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 126) STAGE == Construction
0:00:00.002 4M / 4M INFO General (read_converter.hpp : 67) Binary reads detected
0:00:00.038 4M / 4M INFO General (graph_construction.hpp : 120) Constructing DeBruijn graph for k=33
0:00:00.040 4M / 4M INFO General (kmer_splitters.hpp : 129) Splitting kmer instances into 6400 buckets. This might take a while.
0:00:00.043 4M / 4M INFO General (file_limit.hpp : 30) Open file limit set to 102400
0:00:00.043 4M / 4M INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.54165 Gb
0:00:00.043 4M / 4M INFO General (kmer_index_builder.hpp : 116) Using cell size of 16384
0:02:30.755 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 75484251 reads
0:04:19.083 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 151347777 reads
0:06:07.453 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 228650348 reads
0:07:55.551 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 307847121 reads
0:09:43.817 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 381766453 reads
0:11:31.266 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 457534298 reads
0:13:17.857 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 534390278 reads
0:15:06.607 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 613364011 reads
0:17:10.780 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 692271262 reads
0:19:10.751 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 770399690 reads
0:21:15.354 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 851023791 reads
0:23:14.092 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 929876775 reads
0:25:07.613 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 1006359858 reads
0:27:01.786 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 1083527033 reads
0:28:53.242 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 1161850704 reads
0:30:20.593 139G / 139G INFO General (kmer_splitters.hpp : 153) Processed 1181572310 reads
0:30:20.593 139G / 139G INFO General (kmer_splitters.hpp : 159) Adding contigs from previous K
0:32:39.148 360M / 139G INFO General (kmer_splitters.hpp : 172) Used 1181572310 reads. Maximum read length 150
0:32:39.148 360M / 139G INFO General (kmer_splitters.hpp : 173) Average read length 147.202
0:32:39.148 360M / 139G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
0:36:13.381 360M / 139G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1275767389 kmers in total.
0:36:13.382 360M / 139G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
0:39:50.997 360M / 139G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
0:39:50.997 360M / 139G INFO General (kmer_splitters.hpp : 285) Splitting kmer instances into 1280 buckets. This might take a while.
0:39:50.998 360M / 139G INFO General (file_limit.hpp : 30) Open file limit set to 102400
0:39:50.998 360M / 139G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.5402 Gb
0:39:50.998 360M / 139G INFO General (kmer_index_builder.hpp : 116) Using cell size of 26214
0:43:46.841 44G / 139G INFO General (kmer_splitters.hpp : 304) Processed 1275767389 kmers
0:43:46.841 44G / 139G INFO General (kmer_splitters.hpp : 309) Used 1275767389 kmers.
0:43:54.009 368M / 139G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
0:46:52.002 368M / 139G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1247848459 kmers in total.
0:46:52.002 368M / 139G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
0:50:15.553 368M / 139G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
0:51:53.813 752M / 139G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
0:54:54.942 752M / 139G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 407695616 bytes occupied (2.61375 bits per kmer).
0:54:56.000 1G / 139G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 85) Building k-mer extensions from k+1-mers
0:55:40.675 1G / 139G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 89) Building k-mer extensions from k+1-mers finished.
0:55:40.755 1G / 139G INFO Early tip clipping (early_simplification.hpp : 181) Early tip clipping
0:59:26.398 1G / 139G INFO Early tip clipping (early_simplification.hpp : 184) 186705968 34-mers were removed by early tip clipper
0:59:26.398 1G / 139G INFO General (graph_construction.hpp : 136) Condensing graph
0:59:26.398 1G / 139G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 340) Extracting unbranching paths
1:16:22.360 16G / 139G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths finished. 153595293 sequences extracted
1:16:53.047 16G / 139G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 313) Collecting perfect loops
1:26:09.586 16G / 139G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 329) Collecting perfect loops finished. 1858 loops collected
1:27:14.844 31G / 139G INFO General (graph_construction.hpp : 141) Building index with from graph
1:27:14.847 31G / 139G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
1:27:14.847 31G / 139G INFO General (kmer_splitters.hpp : 214) Splitting kmer instances into 16 buckets. This might take a while.
1:27:14.847 31G / 139G INFO General (file_limit.hpp : 30) Open file limit set to 102400
1:27:14.847 31G / 139G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 272.967 Gb
1:27:14.847 31G / 139G INFO General (kmer_index_builder.hpp : 116) Using cell size of 2097152
1:27:26.290 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 3608476 edges
1:27:35.906 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 7209298 edges
1:27:46.463 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 11231654 edges
1:27:55.894 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 14833064 edges
1:28:05.364 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 18438567 edges
1:28:15.744 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 22244778 edges
1:28:25.781 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 25847081 edges
1:28:36.900 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 29677549 edges
1:28:46.635 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 33285384 edges
1:28:56.466 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 36886446 edges
1:29:07.391 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 40881547 edges
1:29:17.440 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 44488434 edges
1:29:27.434 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 48120044 edges
1:29:40.327 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 51728563 edges
1:29:53.606 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 55337226 edges
1:30:06.447 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 59401072 edges
1:30:38.438 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 70361224 edges
1:33:48.365 31G / 139G INFO General (kmer_splitters.hpp : 225) Processed 137160235 edges
1:34:32.698 31G / 139G INFO General (kmer_splitters.hpp : 230) Used 153597192 sequences.
1:34:32.787 31G / 139G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
1:40:14.488 31G / 139G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1089061421 kmers in total.
1:40:14.488 31G / 139G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
1:43:07.009 31G / 139G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
1:52:52.950 31G / 139G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
1:55:43.152 31G / 139G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 355816912 bytes occupied (2.61375 bits per kmer).
1:55:57.194 55G / 139G INFO General (edge_index_builders.hpp : 27) Collecting k-mer coverage information from graph, this takes a while.
1:56:29.384 55G / 139G INFO General (edge_index.hpp : 91) Index refilled
1:56:47.443 54G / 139G INFO General (graph_construction.hpp : 173) Filling coverage index
1:56:47.443 54G / 139G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from reads, this takes a while.
2:21:33.709 54G / 139G INFO General (graph_construction.hpp : 175) Filling coverage and flanking coverage from index
2:31:20.193 54G / 139G INFO General (construction.cpp : 30) Figured out: read length = 150
2:31:20.223 54G / 139G INFO StageManager (stage.cpp : 126) STAGE == EC Threshold Finding
2:33:07.833 54G / 139G INFO General (kmer_coverage_model.cpp : 182) Kmer coverage valley at: 20
2:33:07.852 54G / 139G INFO General (kmer_coverage_model.cpp : 202) K-mer histogram maximum: 59
2:33:07.852 54G / 139G INFO General (kmer_coverage_model.cpp : 238) Estimated median coverage: 61. Coverage mad: 16.3086
2:33:07.864 54G / 139G INFO General (kmer_coverage_model.cpp : 260) Fitting coverage model
2:33:08.072 54G / 139G INFO General (kmer_coverage_model.cpp : 296) ... iteration 2
2:33:08.479 54G / 139G INFO General (kmer_coverage_model.cpp : 296) ... iteration 4
2:33:09.943 54G / 139G INFO General (kmer_coverage_model.cpp : 296) ... iteration 8
2:33:12.865 54G / 139G INFO General (kmer_coverage_model.cpp : 296) ... iteration 16
2:33:17.780 54G / 139G INFO General (kmer_coverage_model.cpp : 310) Fitted mean coverage: 92.0221. Fitted coverage std. dev: 38.5986
2:33:17.783 54G / 139G INFO General (kmer_coverage_model.cpp : 335) Probability of erroneous kmer at valley: 0.729826
2:33:17.783 54G / 139G INFO General (kmer_coverage_model.cpp : 359) Preliminary threshold calculated as: 34
2:33:17.783 54G / 139G INFO General (kmer_coverage_model.cpp : 363) Threshold adjusted to: 34
2:33:17.783 54G / 139G INFO General (kmer_coverage_model.cpp : 376) Estimated genome size (ignoring repeats): 447318316
2:33:17.794 54G / 139G INFO General (genomic_info_filler.cpp : 133) Mean coverage was calculated as 92.0221
2:33:17.804 54G / 139G INFO General (genomic_info_filler.cpp : 147) EC coverage threshold value was calculated as 34
2:33:17.804 54G / 139G INFO General (genomic_info_filler.cpp : 148) Trusted kmer low bound: 0
2:33:17.804 54G / 139G INFO StageManager (stage.cpp : 126) STAGE == Simplification
2:33:20.658 29G / 139G INFO General (simplification.cpp : 380) Graph simplification started
2:33:20.658 29G / 139G INFO General (simplification.cpp : 76) PROCEDURE == InitialCleaning
2:33:20.658 29G / 139G INFO General (graph_simplification.hpp : 645) Flanking coverage based disconnection disabled
2:33:20.658 29G / 139G INFO General (simplification.cpp : 349) Running Self conjugate edge remover
2:33:29.453 29G / 139G INFO General (simplification.cpp : 351) Triggered 0 times
2:33:29.453 29G / 139G INFO General (simplification.cpp : 349) Running Initial isolated edge remover
2:33:55.488 29G / 139G INFO General (simplification.cpp : 351) Triggered 663429 times
2:33:55.488 29G / 139G INFO General (simplification.cpp : 349) Running Initial tip clipper
2:34:17.618 29G / 139G INFO General (simplification.cpp : 351) Triggered 370262 times
2:34:17.618 29G / 139G INFO General (simplification.cpp : 349) Running Initial ec remover
3:04:04.427 31G / 139G INFO General (simplification.cpp : 351) Triggered 19228267 times
3:04:39.402 30G / 139G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
3:04:39.402 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 1
3:04:39.402 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:04:50.478 30G / 139G INFO General (simplification.cpp : 351) Triggered 258402 times
3:04:50.478 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:34:03.840 30G / 139G INFO General (simplification.cpp : 351) Triggered 3724018 times
3:34:03.841 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:36:17.470 30G / 139G INFO General (simplification.cpp : 351) Triggered 1011860 times
3:36:17.470 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 2
3:36:17.470 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:36:30.506 30G / 139G INFO General (simplification.cpp : 351) Triggered 7339 times
3:36:30.506 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:39:41.884 30G / 139G INFO General (simplification.cpp : 351) Triggered 241831 times
3:39:41.885 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:40:27.888 30G / 139G INFO General (simplification.cpp : 351) Triggered 531327 times
3:40:27.888 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 3
3:40:27.888 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:40:31.089 30G / 139G INFO General (simplification.cpp : 351) Triggered 863 times
3:40:31.089 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:42:29.592 30G / 139G INFO General (simplification.cpp : 351) Triggered 123040 times
3:42:29.592 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:42:41.556 30G / 139G INFO General (simplification.cpp : 351) Triggered 131368 times
3:42:41.556 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 4
3:42:41.556 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:42:43.174 30G / 139G INFO General (simplification.cpp : 351) Triggered 140 times
3:42:43.174 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:43:19.983 30G / 139G INFO General (simplification.cpp : 351) Triggered 36180 times
3:43:19.983 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:43:25.832 30G / 139G INFO General (simplification.cpp : 351) Triggered 55237 times
3:43:25.832 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 5
3:43:25.832 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:43:26.574 30G / 139G INFO General (simplification.cpp : 351) Triggered 70 times
3:43:26.574 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:43:43.619 30G / 139G INFO General (simplification.cpp : 351) Triggered 15210 times
3:43:43.620 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:43:47.261 30G / 139G INFO General (simplification.cpp : 351) Triggered 35891 times
3:43:47.261 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 6
3:43:47.261 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:43:47.673 30G / 139G INFO General (simplification.cpp : 351) Triggered 27 times
3:43:47.673 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:43:56.099 30G / 139G INFO General (simplification.cpp : 351) Triggered 8811 times
3:43:56.099 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:43:58.279 30G / 139G INFO General (simplification.cpp : 351) Triggered 26896 times
3:43:58.279 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 7
3:43:58.279 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:43:58.479 30G / 139G INFO General (simplification.cpp : 351) Triggered 26 times
3:43:58.479 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:44:03.923 30G / 139G INFO General (simplification.cpp : 351) Triggered 5480 times
3:44:03.924 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:44:05.946 30G / 139G INFO General (simplification.cpp : 351) Triggered 26097 times
3:44:05.946 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 8
3:44:05.946 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:44:06.083 30G / 139G INFO General (simplification.cpp : 351) Triggered 9 times
3:44:06.083 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:44:10.240 30G / 139G INFO General (simplification.cpp : 351) Triggered 4466 times
3:44:10.240 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:44:12.512 30G / 139G INFO General (simplification.cpp : 351) Triggered 28049 times
3:44:12.512 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 9
3:44:12.512 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:44:12.638 30G / 139G INFO General (simplification.cpp : 351) Triggered 12 times
3:44:12.638 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:44:16.894 30G / 139G INFO General (simplification.cpp : 351) Triggered 4039 times
3:44:16.895 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:44:19.697 30G / 139G INFO General (simplification.cpp : 351) Triggered 30131 times
3:44:19.697 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 10
3:44:19.697 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:44:19.879 30G / 139G INFO General (simplification.cpp : 351) Triggered 5 times
3:44:19.880 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:44:24.369 30G / 139G INFO General (simplification.cpp : 351) Triggered 4358 times
3:44:24.370 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:44:27.720 30G / 139G INFO General (simplification.cpp : 351) Triggered 36787 times
3:44:27.720 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 11
3:44:27.720 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:44:27.873 30G / 139G INFO General (simplification.cpp : 351) Triggered 2 times
3:44:27.873 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:44:33.360 30G / 139G INFO General (simplification.cpp : 351) Triggered 5208 times
3:44:33.361 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:44:33.361 30G / 139G INFO General (simplification.cpp : 351) Triggered 0 times
3:44:33.362 30G / 139G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 12
3:44:33.362 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:44:33.471 30G / 139G INFO General (simplification.cpp : 351) Triggered 0 times
3:44:33.471 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:44:33.475 30G / 139G INFO General (simplification.cpp : 351) Triggered 0 times
3:44:33.475 30G / 139G INFO General (simplification.cpp : 349) Running Low coverage edge remover
3:44:33.476 30G / 139G INFO General (simplification.cpp : 351) Triggered 0 times
3:44:33.476 30G / 139G INFO General (simplification.cpp : 162) PROCEDURE == Post simplification
3:44:33.476 30G / 139G INFO General (graph_simplification.hpp : 446) Disconnection of relatively low covered edges disabled
3:44:33.476 30G / 139G INFO General (graph_simplification.hpp : 476) Complex tip clipping disabled
3:44:33.477 30G / 139G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
3:44:33.477 30G / 139G INFO General (simplification.cpp : 294) Iteration 0
3:44:33.477 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:44:36.765 30G / 139G INFO General (simplification.cpp : 351) Triggered 72 times
3:44:36.765 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:46:14.002 30G / 139G INFO General (simplification.cpp : 351) Triggered 13438 times
3:46:14.002 30G / 139G INFO General (simplification.cpp : 294) Iteration 1
3:46:14.002 30G / 139G INFO General (simplification.cpp : 349) Running Tip clipper
3:46:14.226 30G / 139G INFO General (simplification.cpp : 351) Triggered 0 times
3:46:14.226 30G / 139G INFO General (simplification.cpp : 349) Running Bulge remover
3:46:14.226 30G / 139G INFO General (simplification.cpp : 351) Triggered 0 times
3:46:14.226 30G / 139G INFO General (simplification.cpp : 326) Disrupting self-conjugate edges
3:46:51.573 30G / 139G INFO StageManager (stage.cpp : 126) STAGE == Simplification Cleanup
3:46:54.052 30G / 139G INFO General (simplification.cpp : 561) Counting average coverage
3:47:06.893 30G / 139G INFO General (simplification.cpp : 566) Average coverage = 164.271
3:47:06.893 30G / 139G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
3:47:06.893 30G / 139G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K33/before_rr.fasta
3:48:36.409 30G / 139G INFO General (contig_output.hpp : 518) Outputting graph to /dat1/Rose_Denovo/resf/spade/ass4//K33/assembly_graph.fastg
3:53:03.168 30G / 139G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K33/simplified_contigs.fasta
3:54:19.224 30G / 139G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K33/final_contigs.fasta
3:55:31.561 30G / 139G INFO General (launch.hpp : 136) SPAdes finished
3:57:20.624 320M / 139G INFO General (main.cpp : 109) Assembling time: 3 hours 57 minutes 20 seconds
== Running assembler: K55
0:00:00.000 4M / 4M INFO General (main.cpp : 75) Loading config from /dat1/Rose_Denovo/resf/spade/ass4/K55/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.hpp : 47) Memory limit set to 850 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Assembling dataset (/dat1/Rose_Denovo/resf/spade/ass4/dataset.info) with K=55
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 : 61) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO General (launch.hpp : 79) Will need read mapping, kmer mapper will be attached
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 126) STAGE == Construction
0:00:00.002 4M / 4M INFO General (read_converter.hpp : 67) Binary reads detected
0:00:00.037 4M / 4M INFO General (graph_construction.hpp : 120) Constructing DeBruijn graph for k=55
0:00:00.039 4M / 4M INFO General (kmer_splitters.hpp : 129) Splitting kmer instances into 6400 buckets. This might take a while.
0:00:00.042 4M / 4M INFO General (file_limit.hpp : 30) Open file limit set to 102400
0:00:00.042 4M / 4M INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.54165 Gb
0:00:00.042 4M / 4M INFO General (kmer_index_builder.hpp : 116) Using cell size of 16384
0:03:09.579 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 137047560 reads
0:05:41.038 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 274463240 reads
0:07:57.395 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 370597621 reads
0:10:27.151 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 507815796 reads
0:13:04.628 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 646391759 reads
0:16:00.108 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 787190993 reads
0:18:52.616 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 916432720 reads
0:21:29.712 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 1047651362 reads
0:24:02.036 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 1175450686 reads
0:24:49.221 139G / 140G INFO General (kmer_splitters.hpp : 153) Processed 1181572310 reads
0:24:49.221 139G / 140G INFO General (kmer_splitters.hpp : 159) Adding contigs from previous K
0:27:26.852 360M / 140G INFO General (kmer_splitters.hpp : 172) Used 1181572310 reads. Maximum read length 150
0:27:26.852 360M / 140G INFO General (kmer_splitters.hpp : 173) Average read length 147.202
0:27:26.852 360M / 140G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
0:31:53.845 360M / 140G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1718822091 kmers in total.
0:31:53.845 360M / 140G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
0:36:43.364 360M / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
0:36:43.364 360M / 140G INFO General (kmer_splitters.hpp : 285) Splitting kmer instances into 1280 buckets. This might take a while.
0:36:43.365 360M / 140G INFO General (file_limit.hpp : 30) Open file limit set to 102400
0:36:43.365 360M / 140G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.5402 Gb
0:36:43.365 360M / 140G INFO General (kmer_index_builder.hpp : 116) Using cell size of 26214
0:41:38.188 44G / 140G INFO General (kmer_splitters.hpp : 304) Processed 1314348381 kmers
0:43:46.162 44G / 140G INFO General (kmer_splitters.hpp : 304) Processed 1718822171 kmers
0:43:46.162 44G / 140G INFO General (kmer_splitters.hpp : 309) Used 1718822171 kmers.
0:43:53.692 368M / 140G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
0:47:55.600 368M / 140G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1705823456 kmers in total.
0:47:55.601 368M / 140G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
0:52:36.094 368M / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
0:54:48.868 880M / 140G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
0:58:52.822 880M / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 557324616 bytes occupied (2.61375 bits per kmer).
0:58:54.388 2G / 140G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 85) Building k-mer extensions from k+1-mers
0:59:58.147 2G / 140G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 89) Building k-mer extensions from k+1-mers finished.
0:59:58.221 2G / 140G INFO General (graph_construction.hpp : 136) Condensing graph
0:59:58.221 2G / 140G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 340) Extracting unbranching paths
1:22:38.061 19G / 140G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths finished. 187985053 sequences extracted
1:23:28.485 19G / 140G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 313) Collecting perfect loops
1:38:29.476 19G / 140G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 329) Collecting perfect loops finished. 128 loops collected
1:40:15.896 42G / 140G INFO General (graph_construction.hpp : 141) Building index with from graph
1:40:15.899 42G / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
1:40:15.899 42G / 140G INFO General (kmer_splitters.hpp : 214) Splitting kmer instances into 16 buckets. This might take a while.
1:40:15.899 42G / 140G INFO General (file_limit.hpp : 30) Open file limit set to 102400
1:40:15.899 42G / 140G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 269.307 Gb
1:40:15.899 42G / 140G INFO General (kmer_index_builder.hpp : 116) Using cell size of 2097152
1:40:26.991 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 2938699 edges
1:40:40.643 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 5870338 edges
1:40:53.339 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 8801141 edges
1:41:04.536 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 11734805 edges
1:41:15.480 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 14669722 edges
1:41:27.000 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 17601901 edges
1:41:38.778 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 20529829 edges
1:41:50.860 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 23460480 edges
1:42:04.644 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 26398584 edges
1:42:17.192 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 29330877 edges
1:42:29.330 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 32260846 edges
1:42:41.783 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 35197227 edges
1:42:54.680 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 38135756 edges
1:43:06.498 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 41066472 edges
1:43:18.172 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 43996954 edges
1:43:29.298 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 46928815 edges
1:44:45.353 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 67474165 edges
1:48:47.341 42G / 140G INFO General (kmer_splitters.hpp : 225) Processed 135010481 edges
1:51:49.794 42G / 140G INFO General (kmer_splitters.hpp : 230) Used 187985245 sequences.
1:51:49.891 42G / 140G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
2:01:31.737 42G / 140G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1718822091 kmers in total.
2:01:31.738 42G / 140G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
2:06:02.080 42G / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
2:22:36.309 42G / 140G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
2:26:42.326 42G / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 561571528 bytes occupied (2.61375 bits per kmer).
2:27:04.357 81G / 140G INFO General (edge_index_builders.hpp : 27) Collecting k-mer coverage information from graph, this takes a while.
2:28:06.305 81G / 140G INFO General (edge_index.hpp : 91) Index refilled
2:28:29.650 78G / 140G INFO General (graph_construction.hpp : 173) Filling coverage index
2:28:29.650 78G / 140G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from reads, this takes a while.
2:49:50.792 78G / 140G INFO General (graph_construction.hpp : 175) Filling coverage and flanking coverage from index
3:06:30.948 78G / 140G INFO General (construction.cpp : 30) Figured out: read length = 150
3:06:30.978 78G / 140G INFO StageManager (stage.cpp : 126) STAGE == EC Threshold Finding
3:08:15.244 78G / 140G INFO General (kmer_coverage_model.cpp : 182) Kmer coverage valley at: 14
3:08:15.249 78G / 140G INFO General (kmer_coverage_model.cpp : 202) K-mer histogram maximum: 46
3:08:15.249 78G / 140G INFO General (kmer_coverage_model.cpp : 238) Estimated median coverage: 48. Coverage mad: 13.3434
3:08:15.251 78G / 140G INFO General (kmer_coverage_model.cpp : 260) Fitting coverage model
3:08:15.395 78G / 140G INFO General (kmer_coverage_model.cpp : 296) ... iteration 2
3:08:15.749 78G / 140G INFO General (kmer_coverage_model.cpp : 296) ... iteration 4
3:08:16.964 78G / 140G INFO General (kmer_coverage_model.cpp : 296) ... iteration 8
3:08:19.468 78G / 140G INFO General (kmer_coverage_model.cpp : 296) ... iteration 16
3:08:22.897 78G / 140G INFO General (kmer_coverage_model.cpp : 310) Fitted mean coverage: 69.4172. Fitted coverage std. dev: 29.3629
3:08:22.899 78G / 140G INFO General (kmer_coverage_model.cpp : 335) Probability of erroneous kmer at valley: 0.71773
3:08:22.899 78G / 140G INFO General (kmer_coverage_model.cpp : 359) Preliminary threshold calculated as: 25
3:08:22.899 78G / 140G INFO General (kmer_coverage_model.cpp : 363) Threshold adjusted to: 25
3:08:22.899 78G / 140G INFO General (kmer_coverage_model.cpp : 376) Estimated genome size (ignoring repeats): 547141713
3:08:22.900 78G / 140G INFO General (genomic_info_filler.cpp : 133) Mean coverage was calculated as 69.4172
3:08:22.907 78G / 140G INFO General (genomic_info_filler.cpp : 147) EC coverage threshold value was calculated as 25
3:08:22.907 78G / 140G INFO General (genomic_info_filler.cpp : 148) Trusted kmer low bound: 0
3:08:22.907 78G / 140G INFO StageManager (stage.cpp : 126) STAGE == Gap Closer
3:08:22.926 78G / 140G INFO General (gap_closer.cpp : 159) Preparing shift maps
3:11:04.512 83G / 140G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
3:18:10.099 85G / 140G INFO General (gap_closer.cpp : 138) Used 295374451 paired reads
3:18:10.099 85G / 140G INFO General (gap_closer.cpp : 140) Merging paired indices
3:19:05.900 79G / 140G INFO GapCloser (gap_closer.cpp : 347) Closing short gaps
3:30:21.817 79G / 140G INFO GapCloser (gap_closer.cpp : 381) Closing short gaps complete: filled 19243 gaps after checking 793347 candidates
3:30:57.506 79G / 140G INFO StageManager (stage.cpp : 126) STAGE == Simplification
3:31:08.028 40G / 140G INFO General (simplification.cpp : 380) Graph simplification started
3:31:08.029 40G / 140G INFO General (simplification.cpp : 76) PROCEDURE == InitialCleaning
3:31:08.029 40G / 140G INFO General (graph_simplification.hpp : 645) Flanking coverage based disconnection disabled
3:31:08.029 40G / 140G INFO General (simplification.cpp : 349) Running Self conjugate edge remover
3:31:24.102 40G / 140G INFO General (simplification.cpp : 351) Triggered 0 times
3:31:24.102 40G / 140G INFO General (simplification.cpp : 349) Running Initial isolated edge remover
3:32:16.839 40G / 140G INFO General (simplification.cpp : 351) Triggered 1328283 times
3:32:16.839 40G / 140G INFO General (simplification.cpp : 349) Running Initial tip clipper
3:56:31.885 41G / 140G INFO General (simplification.cpp : 351) Triggered 27789065 times
3:56:31.885 41G / 140G INFO General (simplification.cpp : 349) Running Initial ec remover
4:13:56.789 41G / 140G INFO General (simplification.cpp : 351) Triggered 9496969 times
4:14:26.996 41G / 140G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
4:14:26.996 41G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 1
4:14:26.996 41G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:14:41.948 41G / 140G INFO General (simplification.cpp : 351) Triggered 461202 times
4:14:41.948 41G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:50:04.424 52G / 140G INFO General (simplification.cpp : 351) Triggered 2437263 times
4:50:04.424 52G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:50:22.826 51G / 140G INFO General (simplification.cpp : 351) Triggered 172741 times
4:50:22.826 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 2
4:50:22.826 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:50:29.681 51G / 140G INFO General (simplification.cpp : 351) Triggered 5312 times
4:50:29.681 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:52:03.744 52G / 140G INFO General (simplification.cpp : 351) Triggered 63435 times
4:52:03.745 52G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:52:31.259 51G / 140G INFO General (simplification.cpp : 351) Triggered 284836 times
4:52:31.259 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 3
4:52:31.259 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:52:33.253 51G / 140G INFO General (simplification.cpp : 351) Triggered 3463 times
4:52:33.253 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:54:48.717 51G / 140G INFO General (simplification.cpp : 351) Triggered 83418 times
4:54:48.717 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:54:53.565 51G / 140G INFO General (simplification.cpp : 351) Triggered 56332 times
4:54:53.565 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 4
4:54:53.565 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:54:54.589 51G / 140G INFO General (simplification.cpp : 351) Triggered 378 times
4:54:54.590 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:55:25.210 51G / 140G INFO General (simplification.cpp : 351) Triggered 19053 times
4:55:25.210 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:55:27.316 51G / 140G INFO General (simplification.cpp : 351) Triggered 25322 times
4:55:27.316 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 5
4:55:27.316 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:55:27.659 51G / 140G INFO General (simplification.cpp : 351) Triggered 139 times
4:55:27.659 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:55:40.279 51G / 140G INFO General (simplification.cpp : 351) Triggered 8232 times
4:55:40.279 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:55:41.583 51G / 140G INFO General (simplification.cpp : 351) Triggered 15373 times
4:55:41.583 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 6
4:55:41.583 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:55:41.807 51G / 140G INFO General (simplification.cpp : 351) Triggered 64 times
4:55:41.808 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:55:47.917 51G / 140G INFO General (simplification.cpp : 351) Triggered 4226 times
4:55:47.918 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:55:48.989 51G / 140G INFO General (simplification.cpp : 351) Triggered 12837 times
4:55:48.989 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 7
4:55:48.989 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:55:49.112 51G / 140G INFO General (simplification.cpp : 351) Triggered 42 times
4:55:49.112 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:55:53.322 51G / 140G INFO General (simplification.cpp : 351) Triggered 2932 times
4:55:53.322 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:55:54.284 51G / 140G INFO General (simplification.cpp : 351) Triggered 11589 times
4:55:54.284 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 8
4:55:54.284 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:55:54.387 51G / 140G INFO General (simplification.cpp : 351) Triggered 45 times
4:55:54.387 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:55:57.570 51G / 140G INFO General (simplification.cpp : 351) Triggered 2183 times
4:55:57.571 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:55:58.573 51G / 140G INFO General (simplification.cpp : 351) Triggered 12147 times
4:55:58.573 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 9
4:55:58.573 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:55:58.654 51G / 140G INFO General (simplification.cpp : 351) Triggered 34 times
4:55:58.654 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:56:01.448 51G / 140G INFO General (simplification.cpp : 351) Triggered 2005 times
4:56:01.448 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:56:02.580 51G / 140G INFO General (simplification.cpp : 351) Triggered 13197 times
4:56:02.580 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 10
4:56:02.580 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:56:02.660 51G / 140G INFO General (simplification.cpp : 351) Triggered 17 times
4:56:02.660 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:56:05.449 51G / 140G INFO General (simplification.cpp : 351) Triggered 1952 times
4:56:05.449 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:56:06.723 51G / 140G INFO General (simplification.cpp : 351) Triggered 15150 times
4:56:06.723 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 11
4:56:06.723 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:56:06.809 51G / 140G INFO General (simplification.cpp : 351) Triggered 17 times
4:56:06.809 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:56:09.586 51G / 140G INFO General (simplification.cpp : 351) Triggered 2142 times
4:56:09.587 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:56:09.587 51G / 140G INFO General (simplification.cpp : 351) Triggered 0 times
4:56:09.587 51G / 140G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 12
4:56:09.587 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:56:09.625 51G / 140G INFO General (simplification.cpp : 351) Triggered 0 times
4:56:09.625 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:56:09.625 51G / 140G INFO General (simplification.cpp : 351) Triggered 0 times
4:56:09.625 51G / 140G INFO General (simplification.cpp : 349) Running Low coverage edge remover
4:56:09.626 51G / 140G INFO General (simplification.cpp : 351) Triggered 0 times
4:56:09.626 51G / 140G INFO General (simplification.cpp : 162) PROCEDURE == Post simplification
4:56:09.626 51G / 140G INFO General (graph_simplification.hpp : 446) Disconnection of relatively low covered edges disabled
4:56:09.626 51G / 140G INFO General (graph_simplification.hpp : 476) Complex tip clipping disabled
4:56:09.626 51G / 140G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
4:56:09.627 51G / 140G INFO General (simplification.cpp : 294) Iteration 0
4:56:09.627 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:56:11.805 51G / 140G INFO General (simplification.cpp : 351) Triggered 35 times
4:56:11.806 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:56:48.996 51G / 140G INFO General (simplification.cpp : 351) Triggered 5588 times
4:56:48.996 51G / 140G INFO General (simplification.cpp : 294) Iteration 1
4:56:48.996 51G / 140G INFO General (simplification.cpp : 349) Running Tip clipper
4:56:49.070 51G / 140G INFO General (simplification.cpp : 351) Triggered 0 times
4:56:49.070 51G / 140G INFO General (simplification.cpp : 349) Running Bulge remover
4:56:49.070 51G / 140G INFO General (simplification.cpp : 351) Triggered 0 times
4:56:49.070 51G / 140G INFO General (simplification.cpp : 326) Disrupting self-conjugate edges
4:57:10.340 51G / 140G INFO StageManager (stage.cpp : 126) STAGE == Gap Closer
4:57:10.340 51G / 140G INFO General (graph_pack.hpp : 96) Index refill
4:57:10.344 51G / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
4:57:10.344 51G / 140G INFO General (kmer_splitters.hpp : 214) Splitting kmer instances into 16 buckets. This might take a while.
4:57:10.344 51G / 140G INFO General (file_limit.hpp : 30) Open file limit set to 102400
4:57:10.344 51G / 140G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 266.125 Gb
4:57:10.344 51G / 140G INFO General (kmer_index_builder.hpp : 116) Using cell size of 2097152
4:57:19.409 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 704223 edges
4:57:28.860 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 1411028 edges
4:57:38.058 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 2115648 edges
4:57:47.477 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 2822678 edges
4:57:57.398 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 3536852 edges
4:58:06.907 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 4248556 edges
4:58:16.398 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 4960034 edges
4:58:25.856 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 5670168 edges
4:58:35.703 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 6388139 edges
4:58:45.703 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 7103093 edges
4:58:55.850 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 7818359 edges
4:59:06.037 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 8537924 edges
4:59:16.181 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 9257810 edges
4:59:26.415 52G / 140G INFO General (kmer_splitters.hpp : 225) Processed 9983417 edges
4:59:41.041 52G / 140G INFO General (kmer_splitters.hpp : 230) Used 10990907 sequences.
4:59:41.142 51G / 140G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
5:02:00.907 51G / 140G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 498984812 kmers in total.
5:02:00.907 51G / 140G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
5:03:20.973 51G / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
5:07:42.944 51G / 140G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
5:09:02.978 51G / 140G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 163027808 bytes occupied (2.61375 bits per kmer).
5:09:09.643 62G / 140G INFO General (edge_index_builders.hpp : 27) Collecting k-mer coverage information from graph, this takes a while.
5:09:21.366 62G / 140G INFO General (edge_index.hpp : 91) Index refilled
5:09:21.394 62G / 140G INFO General (gap_closer.cpp : 159) Preparing shift maps
5:09:30.316 63G / 140G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
5:19:06.807 63G / 140G INFO General (gap_closer.cpp : 138) Used 295374451 paired reads
5:19:06.807 63G / 140G INFO General (gap_closer.cpp : 140) Merging paired indices
5:19:08.505 63G / 140G INFO GapCloser (gap_closer.cpp : 347) Closing short gaps
5:19:40.164 63G / 140G INFO GapCloser (gap_closer.cpp : 381) Closing short gaps complete: filled 960 gaps after checking 44579 candidates
5:19:45.478 63G / 140G INFO StageManager (stage.cpp : 126) STAGE == Simplification Cleanup
5:19:59.962 62G / 140G INFO General (simplification.cpp : 561) Counting average coverage
5:20:04.076 62G / 140G INFO General (simplification.cpp : 566) Average coverage = 107.831
5:20:04.076 62G / 140G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
5:20:04.076 62G / 140G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K55/before_rr.fasta
5:21:08.542 62G / 140G INFO General (contig_output.hpp : 518) Outputting graph to /dat1/Rose_Denovo/resf/spade/ass4//K55/assembly_graph.fastg
5:24:21.067 62G / 140G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K55/simplified_contigs.fasta
5:25:16.236 62G / 140G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K55/final_contigs.fasta
5:26:10.203 62G / 140G INFO General (launch.hpp : 136) SPAdes finished
5:33:37.458 320M / 140G INFO General (main.cpp : 109) Assembling time: 5 hours 33 minutes 37 seconds
== Running assembler: K77
0:00:00.000 4M / 4M INFO General (main.cpp : 75) Loading config from /dat1/Rose_Denovo/resf/spade/ass4/K77/configs/config.info
0:00:00.000 4M / 4M INFO General (memory_limit.hpp : 47) Memory limit set to 850 Gb
0:00:00.000 4M / 4M INFO General (main.cpp : 88) Starting SPAdes, built from N/A, git revision N/A
0:00:00.000 4M / 4M INFO General (main.cpp : 89) Maximum k-mer length: 128
0:00:00.000 4M / 4M INFO General (main.cpp : 90) Assembling dataset (/dat1/Rose_Denovo/resf/spade/ass4/dataset.info) with K=77
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 : 61) Two-step RR enabled: 0
0:00:00.001 4M / 4M INFO General (launch.hpp : 79) Will need read mapping, kmer mapper will be attached
0:00:00.001 4M / 4M INFO StageManager (stage.cpp : 126) STAGE == Construction
0:00:00.002 4M / 4M INFO General (read_converter.hpp : 67) Binary reads detected
0:00:00.041 4M / 4M INFO General (graph_construction.hpp : 120) Constructing DeBruijn graph for k=77
0:00:00.042 4M / 4M INFO General (kmer_splitters.hpp : 129) Splitting kmer instances into 6400 buckets. This might take a while.
0:00:00.046 4M / 4M INFO General (file_limit.hpp : 30) Open file limit set to 102400
0:00:00.046 4M / 4M INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.54165 Gb
0:00:00.046 4M / 4M INFO General (kmer_index_builder.hpp : 116) Using cell size of 16384
0:05:00.056 207G / 209G INFO General (kmer_splitters.hpp : 153) Processed 214732837 reads
0:08:32.251 207G / 209G INFO General (kmer_splitters.hpp : 153) Processed 355974907 reads
0:12:34.984 207G / 209G INFO General (kmer_splitters.hpp : 153) Processed 571026057 reads
0:17:31.198 207G / 209G INFO General (kmer_splitters.hpp : 153) Processed 773281265 reads
0:21:52.992 207G / 209G INFO General (kmer_splitters.hpp : 153) Processed 940742552 reads
0:26:05.958 207G / 209G INFO General (kmer_splitters.hpp : 153) Processed 1118654299 reads
0:28:55.560 207G / 209G INFO General (kmer_splitters.hpp : 153) Processed 1181572310 reads
0:28:55.560 207G / 209G INFO General (kmer_splitters.hpp : 159) Adding contigs from previous K
0:33:35.628 368M / 209G INFO General (kmer_splitters.hpp : 172) Used 1181572310 reads. Maximum read length 150
0:33:35.628 368M / 209G INFO General (kmer_splitters.hpp : 173) Average read length 147.202
0:33:35.628 368M / 209G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
0:40:30.661 368M / 209G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1847760165 kmers in total.
0:40:30.661 368M / 209G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
0:48:13.284 368M / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
0:48:13.284 368M / 209G INFO General (kmer_splitters.hpp : 285) Splitting kmer instances into 1280 buckets. This might take a while.
0:48:13.285 368M / 209G INFO General (file_limit.hpp : 30) Open file limit set to 102400
0:48:13.285 368M / 209G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 3.54017 Gb
0:48:13.285 368M / 209G INFO General (kmer_index_builder.hpp : 116) Using cell size of 17476
0:54:02.858 44G / 209G INFO General (kmer_splitters.hpp : 304) Processed 872558660 kmers
0:59:53.232 44G / 209G INFO General (kmer_splitters.hpp : 304) Processed 1744524431 kmers
1:00:48.782 44G / 209G INFO General (kmer_splitters.hpp : 304) Processed 1847760325 kmers
1:00:48.782 44G / 209G INFO General (kmer_splitters.hpp : 309) Used 1847760325 kmers.
1:00:56.298 376M / 209G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
1:07:28.410 376M / 209G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1847638766 kmers in total.
1:07:28.411 376M / 209G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
1:15:09.417 376M / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
1:17:52.547 1016M / 209G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
1:24:43.966 1016M / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 603658368 bytes occupied (2.61375 bits per kmer).
1:24:45.528 2G / 209G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 85) Building k-mer extensions from k+1-mers
1:26:07.319 2G / 209G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 89) Building k-mer extensions from k+1-mers finished.
1:26:07.421 2G / 209G INFO General (graph_construction.hpp : 136) Condensing graph
1:26:07.421 2G / 209G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 340) Extracting unbranching paths
1:51:37.545 20G / 209G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 354) Extracting unbranching paths finished. 163075512 sequences extracted
1:52:31.667 20G / 209G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 313) Collecting perfect loops
2:09:53.350 20G / 209G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 329) Collecting perfect loops finished. 132 loops collected
2:11:25.542 40G / 209G INFO General (graph_construction.hpp : 141) Building index with from graph
2:11:25.546 40G / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
2:11:25.546 40G / 209G INFO General (kmer_splitters.hpp : 214) Splitting kmer instances into 16 buckets. This might take a while.
2:11:25.546 40G / 209G INFO General (file_limit.hpp : 30) Open file limit set to 102400
2:11:25.546 40G / 209G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 269.737 Gb
2:11:25.546 40G / 209G INFO General (kmer_index_builder.hpp : 116) Using cell size of 1398101
2:11:33.953 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 1638838 edges
2:11:42.796 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 3279484 edges
2:11:51.427 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 4917115 edges
2:11:59.861 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 6552055 edges
2:12:08.297 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 8188145 edges
2:12:16.603 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 9825940 edges
2:12:25.346 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 11534807 edges
2:12:33.608 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 13174383 edges
2:12:41.763 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 14813458 edges
2:12:50.109 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 16450870 edges
2:12:58.508 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 18089125 edges
2:13:06.899 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 19727680 edges
2:13:15.721 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 21485458 edges
2:13:23.906 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 23121641 edges
2:13:32.315 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 24760377 edges
2:14:27.555 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 34740359 edges
2:17:24.425 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 67678213 edges
2:23:35.849 41G / 209G INFO General (kmer_splitters.hpp : 225) Processed 135446041 edges
2:26:06.457 41G / 209G INFO General (kmer_splitters.hpp : 230) Used 163075742 sequences.
2:26:06.539 40G / 209G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
2:39:45.697 40G / 209G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 1847760165 kmers in total.
2:39:45.697 40G / 209G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
2:47:34.979 40G / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
3:06:32.081 41G / 209G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
3:13:31.085 41G / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 603698040 bytes occupied (2.61375 bits per kmer).
3:13:55.968 82G / 209G INFO General (edge_index_builders.hpp : 27) Collecting k-mer coverage information from graph, this takes a while.
3:14:52.912 82G / 209G INFO General (edge_index.hpp : 91) Index refilled
3:15:21.095 80G / 209G INFO General (graph_construction.hpp : 173) Filling coverage index
3:15:21.095 80G / 209G INFO General (edge_index_builders.hpp : 105) Collecting k-mer coverage information from reads, this takes a while.
3:32:53.158 80G / 209G INFO General (graph_construction.hpp : 175) Filling coverage and flanking coverage from index
3:50:25.208 80G / 209G INFO General (construction.cpp : 30) Figured out: read length = 150
3:50:25.237 80G / 209G INFO StageManager (stage.cpp : 126) STAGE == EC Threshold Finding
3:52:49.422 80G / 209G INFO General (kmer_coverage_model.cpp : 182) Kmer coverage valley at: 10
3:52:49.425 80G / 209G INFO General (kmer_coverage_model.cpp : 202) K-mer histogram maximum: 35
3:52:49.425 80G / 209G INFO General (kmer_coverage_model.cpp : 238) Estimated median coverage: 37. Coverage mad: 11.8608
3:52:49.427 80G / 209G INFO General (kmer_coverage_model.cpp : 260) Fitting coverage model
3:52:49.520 80G / 209G INFO General (kmer_coverage_model.cpp : 296) ... iteration 2
3:52:49.761 80G / 209G INFO General (kmer_coverage_model.cpp : 296) ... iteration 4
3:52:50.672 80G / 209G INFO General (kmer_coverage_model.cpp : 296) ... iteration 8
3:52:52.719 80G / 209G INFO General (kmer_coverage_model.cpp : 296) ... iteration 16
3:52:56.244 80G / 209G INFO General (kmer_coverage_model.cpp : 296) ... iteration 32
3:52:57.112 80G / 209G INFO General (kmer_coverage_model.cpp : 310) Fitted mean coverage: 50.4701. Fitted coverage std. dev: 21.6943
3:52:57.113 80G / 209G INFO General (kmer_coverage_model.cpp : 335) Probability of erroneous kmer at valley: 0.635512
3:52:57.113 80G / 209G INFO General (kmer_coverage_model.cpp : 359) Preliminary threshold calculated as: 18
3:52:57.113 80G / 209G INFO General (kmer_coverage_model.cpp : 363) Threshold adjusted to: 18
3:52:57.113 80G / 209G INFO General (kmer_coverage_model.cpp : 376) Estimated genome size (ignoring repeats): 607635532
3:52:57.114 80G / 209G INFO General (genomic_info_filler.cpp : 133) Mean coverage was calculated as 50.4701
3:52:57.119 80G / 209G INFO General (genomic_info_filler.cpp : 147) EC coverage threshold value was calculated as 18
3:52:57.119 80G / 209G INFO General (genomic_info_filler.cpp : 148) Trusted kmer low bound: 0
3:52:57.119 80G / 209G INFO StageManager (stage.cpp : 126) STAGE == Gap Closer
3:52:57.138 80G / 209G INFO General (gap_closer.cpp : 159) Preparing shift maps
3:56:16.561 86G / 209G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
4:00:42.533 89G / 209G INFO General (gap_closer.cpp : 138) Used 295374451 paired reads
4:00:42.535 89G / 209G INFO General (gap_closer.cpp : 140) Merging paired indices
4:02:00.152 81G / 209G INFO GapCloser (gap_closer.cpp : 347) Closing short gaps
4:10:52.859 81G / 209G INFO GapCloser (gap_closer.cpp : 381) Closing short gaps complete: filled 15716 gaps after checking 851050 candidates
4:11:19.977 80G / 209G INFO StageManager (stage.cpp : 126) STAGE == Simplification
4:11:29.056 38G / 209G INFO General (simplification.cpp : 380) Graph simplification started
4:11:29.056 38G / 209G INFO General (simplification.cpp : 76) PROCEDURE == InitialCleaning
4:11:29.060 38G / 209G INFO General (graph_simplification.hpp : 645) Flanking coverage based disconnection disabled
4:11:29.060 38G / 209G INFO General (simplification.cpp : 349) Running Self conjugate edge remover
4:11:37.256 38G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
4:11:37.257 38G / 209G INFO General (simplification.cpp : 349) Running Initial isolated edge remover
4:13:05.926 38G / 209G INFO General (simplification.cpp : 351) Triggered 4648857 times
4:13:05.926 38G / 209G INFO General (simplification.cpp : 349) Running Initial tip clipper
4:37:37.887 39G / 209G INFO General (simplification.cpp : 351) Triggered 32517067 times
4:37:37.887 39G / 209G INFO General (simplification.cpp : 349) Running Initial ec remover
4:41:35.172 39G / 209G INFO General (simplification.cpp : 351) Triggered 2136909 times
4:41:52.646 38G / 209G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
4:41:52.646 38G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 1
4:41:52.646 38G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
4:42:07.054 38G / 209G INFO General (simplification.cpp : 351) Triggered 400786 times
4:42:07.054 38G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:09:34.812 47G / 209G INFO General (simplification.cpp : 351) Triggered 1557513 times
5:09:34.812 47G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:09:37.893 47G / 209G INFO General (simplification.cpp : 351) Triggered 2227 times
5:09:37.893 47G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 2
5:09:37.893 47G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:09:42.358 47G / 209G INFO General (simplification.cpp : 351) Triggered 2231 times
5:09:42.358 47G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:09:44.122 47G / 209G INFO General (simplification.cpp : 351) Triggered 1092 times
5:09:44.122 47G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:09:54.596 46G / 209G INFO General (simplification.cpp : 351) Triggered 108336 times
5:09:54.596 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 3
5:09:54.596 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:09:55.310 46G / 209G INFO General (simplification.cpp : 351) Triggered 5310 times
5:09:55.311 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:11:10.075 47G / 209G INFO General (simplification.cpp : 351) Triggered 37733 times
5:11:10.075 47G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:11:14.816 46G / 209G INFO General (simplification.cpp : 351) Triggered 34248 times
5:11:14.816 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 4
5:11:14.816 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:11:15.666 46G / 209G INFO General (simplification.cpp : 351) Triggered 1155 times
5:11:15.666 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:11:39.170 47G / 209G INFO General (simplification.cpp : 351) Triggered 12215 times
5:11:39.170 47G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:11:40.802 46G / 209G INFO General (simplification.cpp : 351) Triggered 14058 times
5:11:40.802 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 5
5:11:40.802 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:11:41.107 46G / 209G INFO General (simplification.cpp : 351) Triggered 327 times
5:11:41.107 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:11:49.730 46G / 209G INFO General (simplification.cpp : 351) Triggered 4711 times
5:11:49.730 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:11:50.709 46G / 209G INFO General (simplification.cpp : 351) Triggered 8555 times
5:11:50.709 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 6
5:11:50.709 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:11:50.839 46G / 209G INFO General (simplification.cpp : 351) Triggered 214 times
5:11:50.839 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:11:54.849 46G / 209G INFO General (simplification.cpp : 351) Triggered 2458 times
5:11:54.849 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:11:55.646 46G / 209G INFO General (simplification.cpp : 351) Triggered 6757 times
5:11:55.646 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 7
5:11:55.646 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:11:55.729 46G / 209G INFO General (simplification.cpp : 351) Triggered 135 times
5:11:55.729 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:11:58.546 46G / 209G INFO General (simplification.cpp : 351) Triggered 1638 times
5:11:58.546 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:11:59.272 46G / 209G INFO General (simplification.cpp : 351) Triggered 6480 times
5:11:59.272 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 8
5:11:59.272 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:11:59.336 46G / 209G INFO General (simplification.cpp : 351) Triggered 115 times
5:11:59.336 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:01.527 46G / 209G INFO General (simplification.cpp : 351) Triggered 1305 times
5:12:01.527 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:12:02.255 46G / 209G INFO General (simplification.cpp : 351) Triggered 6648 times
5:12:02.255 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 9
5:12:02.255 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:12:02.315 46G / 209G INFO General (simplification.cpp : 351) Triggered 85 times
5:12:02.315 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:04.417 46G / 209G INFO General (simplification.cpp : 351) Triggered 1140 times
5:12:04.417 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:12:05.186 46G / 209G INFO General (simplification.cpp : 351) Triggered 7027 times
5:12:05.186 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 10
5:12:05.186 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:12:05.238 46G / 209G INFO General (simplification.cpp : 351) Triggered 69 times
5:12:05.238 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:07.064 46G / 209G INFO General (simplification.cpp : 351) Triggered 1086 times
5:12:07.065 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:12:07.958 46G / 209G INFO General (simplification.cpp : 351) Triggered 8269 times
5:12:07.958 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 11
5:12:07.958 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:12:08.013 46G / 209G INFO General (simplification.cpp : 351) Triggered 50 times
5:12:08.013 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:09.778 46G / 209G INFO General (simplification.cpp : 351) Triggered 1103 times
5:12:09.778 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:12:09.778 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:09.778 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 12
5:12:09.778 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:12:09.796 46G / 209G INFO General (simplification.cpp : 351) Triggered 5 times
5:12:09.796 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:09.796 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:09.796 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:12:09.796 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:09.796 46G / 209G INFO General (simplification.cpp : 403) PROCEDURE == Simplification cycle, iteration 13
5:12:09.796 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:12:09.796 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:09.796 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:09.796 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:09.796 46G / 209G INFO General (simplification.cpp : 349) Running Low coverage edge remover
5:12:09.796 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:09.796 46G / 209G INFO General (simplification.cpp : 162) PROCEDURE == Post simplification
5:12:09.796 46G / 209G INFO General (graph_simplification.hpp : 446) Disconnection of relatively low covered edges disabled
5:12:09.796 46G / 209G INFO General (graph_simplification.hpp : 476) Complex tip clipping disabled
5:12:09.796 46G / 209G INFO General (graph_simplification.hpp : 617) Creating parallel br instance
5:12:09.796 46G / 209G INFO General (simplification.cpp : 294) Iteration 0
5:12:09.796 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:12:11.876 46G / 209G INFO General (simplification.cpp : 351) Triggered 57 times
5:12:11.876 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:27.948 46G / 209G INFO General (simplification.cpp : 351) Triggered 3111 times
5:12:27.948 46G / 209G INFO General (simplification.cpp : 294) Iteration 1
5:12:27.948 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:12:27.974 46G / 209G INFO General (simplification.cpp : 351) Triggered 1 times
5:12:27.974 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:27.975 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:27.975 46G / 209G INFO General (simplification.cpp : 294) Iteration 2
5:12:27.975 46G / 209G INFO General (simplification.cpp : 349) Running Tip clipper
5:12:27.975 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:27.975 46G / 209G INFO General (simplification.cpp : 349) Running Bulge remover
5:12:27.976 46G / 209G INFO General (simplification.cpp : 351) Triggered 0 times
5:12:27.976 46G / 209G INFO General (simplification.cpp : 326) Disrupting self-conjugate edges
5:12:39.746 46G / 209G INFO StageManager (stage.cpp : 126) STAGE == Gap Closer
5:12:39.746 46G / 209G INFO General (graph_pack.hpp : 96) Index refill
5:12:39.753 46G / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
5:12:39.753 46G / 209G INFO General (kmer_splitters.hpp : 214) Splitting kmer instances into 16 buckets. This might take a while.
5:12:39.753 46G / 209G INFO General (file_limit.hpp : 30) Open file limit set to 102400
5:12:39.753 46G / 209G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 267.827 Gb
5:12:39.753 46G / 209G INFO General (kmer_index_builder.hpp : 116) Using cell size of 1398101
5:12:47.649 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 274550 edges
5:12:57.880 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 551465 edges
5:13:09.813 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 822802 edges
5:13:18.698 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 1093307 edges
5:13:31.360 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 1368621 edges
5:13:39.562 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 1643026 edges
5:13:51.088 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 1918801 edges
5:14:01.904 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 2190046 edges
5:14:10.104 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 2462822 edges
5:14:23.886 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 2738312 edges
5:14:32.032 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 3009067 edges
5:14:42.834 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 3282457 edges
5:15:26.173 47G / 209G INFO General (kmer_splitters.hpp : 225) Processed 4378359 edges
5:17:05.580 47G / 209G INFO General (kmer_splitters.hpp : 230) Used 6922027 sequences.
5:17:05.678 46G / 209G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
5:21:39.316 46G / 209G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 552671532 kmers in total.
5:21:39.316 46G / 209G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
5:24:43.156 46G / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
5:29:34.679 46G / 209G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
5:32:40.537 46G / 209G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 180568272 bytes occupied (2.61375 bits per kmer).
5:32:52.284 59G / 209G INFO General (edge_index_builders.hpp : 27) Collecting k-mer coverage information from graph, this takes a while.
5:33:03.029 59G / 209G INFO General (edge_index.hpp : 91) Index refilled
5:33:03.060 59G / 209G INFO General (gap_closer.cpp : 159) Preparing shift maps
5:33:10.749 59G / 209G INFO General (gap_closer.cpp : 119) Processing paired reads (takes a while)
5:40:47.703 59G / 209G INFO General (gap_closer.cpp : 138) Used 295374451 paired reads
5:40:47.703 59G / 209G INFO General (gap_closer.cpp : 140) Merging paired indices
5:40:49.379 59G / 209G INFO GapCloser (gap_closer.cpp : 347) Closing short gaps
5:41:08.065 59G / 209G INFO GapCloser (gap_closer.cpp : 381) Closing short gaps complete: filled 311 gaps after checking 37887 candidates
5:41:11.941 59G / 209G INFO StageManager (stage.cpp : 126) STAGE == Simplification Cleanup
5:41:32.779 58G / 209G INFO General (simplification.cpp : 561) Counting average coverage
5:41:37.862 58G / 209G INFO General (simplification.cpp : 566) Average coverage = 73.8357
5:41:37.862 58G / 209G INFO StageManager (stage.cpp : 126) STAGE == Mismatch Correction
5:41:37.862 58G / 209G INFO General (graph_pack.hpp : 105) Normalizing k-mer map. Total 309233846 kmers to process
5:49:13.308 58G / 209G INFO General (graph_pack.hpp : 107) Normalizing done
6:44:51.527 311G / 311G INFO General (mismatch_shall_not_pass.hp: 187) Finished collecting potential mismatches positions
7:06:13.260 61G / 311G INFO General (mismatch_shall_not_pass.hp: 284) All edges processed
7:06:29.675 58G / 311G INFO General (mismatch_correction.cpp : 26) Corrected 6249 nucleotides
7:06:29.702 58G / 311G INFO StageManager (stage.cpp : 126) STAGE == Hybrid Aligning
7:06:29.702 58G / 311G INFO General (hybrid_aligning.cpp : 398) Hybrid library detected: #1
7:06:29.702 58G / 311G INFO General (hybrid_aligning.cpp : 334) Aligning library with Pacbio aligner
7:06:29.702 58G / 311G INFO General (hybrid_aligning.cpp : 336) Using seed size: 13
7:06:29.704 58G / 311G INFO General (edge_multi_index.hpp : 111) Constructing multi-kmer index
7:06:29.705 58G / 311G INFO K-mer Index Building (kmer_index_builder.hpp : 428) Building kmer index
7:06:29.705 58G / 311G INFO General (kmer_splitters.hpp : 214) Splitting kmer instances into 16 buckets. This might take a while.
7:06:29.705 58G / 311G INFO General (file_limit.hpp : 30) Open file limit set to 102400
7:06:29.705 58G / 311G INFO General (kmer_index_builder.hpp : 108) Memory available for splitting buffers: 263.846 Gb
7:06:29.705 58G / 311G INFO General (kmer_index_builder.hpp : 116) Using cell size of 4194304
7:06:36.003 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 293899 edges
7:06:43.111 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 586631 edges
7:06:49.794 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 878079 edges
7:06:56.832 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 1169006 edges
7:07:03.639 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 1462037 edges
7:07:10.506 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 1755521 edges
7:07:17.373 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 2047101 edges
7:07:24.254 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 2339690 edges
7:07:31.095 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 2632165 edges
7:07:37.902 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 2923395 edges
7:07:44.841 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 3216168 edges
7:07:51.473 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 3509648 edges
7:08:11.813 59G / 311G INFO General (kmer_splitters.hpp : 225) Processed 4386888 edges
7:09:05.565 59G / 311G INFO General (kmer_splitters.hpp : 230) Used 6701075 sequences.
7:09:05.669 58G / 311G INFO General (kmer_index_builder.hpp : 252) Starting k-mer counting.
7:10:06.042 58G / 311G INFO General (kmer_index_builder.hpp : 258) K-mer counting done. There are 63739638 kmers in total.
7:10:06.042 58G / 311G INFO General (kmer_index_builder.hpp : 260) Merging temporary buckets.
7:10:11.510 58G / 311G INFO K-mer Index Building (kmer_index_builder.hpp : 437) Building perfect hash indices
7:10:35.237 58G / 311G INFO General (kmer_index_builder.hpp : 276) Merging final buckets.
7:10:40.775 58G / 311G INFO K-mer Index Building (kmer_index_builder.hpp : 483) Index built. Total 20825064 bytes occupied (2.61377 bits per kmer).
7:10:42.040 60G / 311G INFO General (perfect_hash_map.hpp : 185) Arranging kmers in hash map order
7:11:08.699 60G / 311G INFO General (perfect_hash_map.hpp : 197) Done. Total swaps: 63739402
7:11:08.701 60G / 311G INFO General (edge_index_builders.hpp : 27) Collecting k-mer coverage information from graph, this takes a while.
7:11:43.339 110G / 311G INFO PacIndex (pac_index.hpp : 85) Index constructed
7:11:46.975 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 0 of 50000 reads.
8:38:38.107 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47625 of them longer than 500; among long reads aligned: 4953; paths of more than one edge received: 350
8:38:38.220 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 50000 reads
8:38:42.032 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 1 of 50000 reads.
10:02:06.643 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47456 of them longer than 500; among long reads aligned: 4830; paths of more than one edge received: 323
10:02:06.799 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 100000 reads
10:02:10.550 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 2 of 50000 reads.
11:22:05.948 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47440 of them longer than 500; among long reads aligned: 4717; paths of more than one edge received: 362
11:22:06.093 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 150000 reads
11:22:09.940 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 3 of 50000 reads.
12:42:15.078 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47522 of them longer than 500; among long reads aligned: 4622; paths of more than one edge received: 351
12:42:15.224 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 200000 reads
12:42:18.942 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 4 of 50000 reads.
14:05:13.205 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47565 of them longer than 500; among long reads aligned: 4788; paths of more than one edge received: 334
14:05:13.366 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 250000 reads
14:05:17.227 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 5 of 50000 reads.
15:27:34.328 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47565 of them longer than 500; among long reads aligned: 4716; paths of more than one edge received: 350
15:27:34.509 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 300000 reads
15:27:38.192 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 6 of 50000 reads.
16:48:17.592 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47565 of them longer than 500; among long reads aligned: 4727; paths of more than one edge received: 365
16:48:17.743 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 350000 reads
16:48:21.403 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 7 of 50000 reads.
18:06:30.842 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47462 of them longer than 500; among long reads aligned: 4642; paths of more than one edge received: 331
18:06:30.995 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 400000 reads
18:06:34.570 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 8 of 50000 reads.
19:28:02.166 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47395 of them longer than 500; among long reads aligned: 4656; paths of more than one edge received: 359
19:28:02.312 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 450000 reads
19:28:05.762 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 9 of 50000 reads.
20:47:23.911 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47342 of them longer than 500; among long reads aligned: 4781; paths of more than one edge received: 350
20:47:24.026 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 500000 reads
20:47:27.725 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 10 of 50000 reads.
22:03:20.846 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47235 of them longer than 500; among long reads aligned: 4835; paths of more than one edge received: 349
22:03:21.019 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 550000 reads
22:03:25.445 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 11 of 50000 reads.
23:24:47.380 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47127 of them longer than 500; among long reads aligned: 4519; paths of more than one edge received: 323
23:24:47.541 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 600000 reads
23:24:50.971 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 12 of 50000 reads.
24:38:15.982 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47194 of them longer than 500; among long reads aligned: 4666; paths of more than one edge received: 347
24:38:16.148 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 650000 reads
24:38:19.601 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 13 of 50000 reads.
25:52:54.579 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 50000 processed; 47144 of them longer than 500; among long reads aligned: 4261; paths of more than one edge received: 299
25:52:54.712 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 700000 reads
25:52:55.932 111G / 311G INFO General (hybrid_aligning.cpp : 315) Prepared batch 14 of 14486 reads.
26:20:12.259 111G / 311G INFO General (hybrid_aligning.cpp : 280) Read batch of size: 14486 processed; 13709 of them longer than 500; among long reads aligned: 1279; paths of more than one edge received: 87
26:20:12.322 111G / 311G INFO General (hybrid_aligning.cpp : 320) Processed 714486 reads
26:20:12.428 110G / 311G INFO General (hybrid_aligning.cpp : 351) For library of long reads :
26:20:12.428 110G / 311G INFO StatsCounter (pacbio_read_structures.hpp: 250) Median fraction of present seeds in maximal alignmnent among reads aligned to the graph: 0.095
26:20:12.428 110G / 311G INFO General (hybrid_aligning.cpp : 353) PacBio aligning finished
26:22:50.809 58G / 311G INFO General (hybrid_aligning.cpp : 446) Padding gaps
26:22:50.809 58G / 311G INFO General (hybrid_aligning.cpp : 450) Min gap weight set to 2
26:22:50.809 58G / 311G INFO General (hybrid_aligning.cpp : 359) Closing gaps with long reads
26:22:50.974 58G / 311G INFO MultiGapJoiner (hybrid_gap_closer.hpp : 559) Closed 3 gaps
26:22:51.966 58G / 311G INFO General (hybrid_aligning.cpp : 379) Closing gaps with long reads finished
26:22:51.966 58G / 311G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
26:22:51.966 58G / 311G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K77/pre_pe_before_rr.fasta
26:23:35.251 58G / 311G INFO General (contig_output.hpp : 518) Outputting graph to /dat1/Rose_Denovo/resf/spade/ass4//K77/pre_pe_assembly_graph.fastg
26:25:49.329 58G / 311G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K77/pre_pe_simplified_contigs.fasta
26:26:40.260 58G / 311G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K77/pre_pe_final_contigs.fasta
26:27:30.169 58G / 311G INFO StageManager (stage.cpp : 126) STAGE == Paired Information Counting
26:28:44.595 60G / 311G INFO General (graph_pack.hpp : 105) Normalizing k-mer map. Total 309849432 kmers to process
26:33:38.136 60G / 311G INFO General (graph_pack.hpp : 107) Normalizing done
26:33:43.487 60G / 311G INFO General (pair_info_count.cpp : 300) Min edge length for estimation: 669
26:33:43.487 60G / 311G INFO General (pair_info_count.cpp : 311) Estimating insert size for library #0
26:33:43.487 60G / 311G INFO General (pair_info_count.cpp : 116) Estimating insert size (takes a while)
26:33:44.423 61G / 311G INFO General (short_read_mapper.hpp : 88) Selecting usual mapper
26:34:05.962 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 200000 reads
26:34:06.020 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 400000 reads
26:34:06.223 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 600000 reads
26:34:06.270 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 800000 reads
26:34:06.445 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 1000000 reads
26:34:06.598 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 1200000 reads
26:34:08.657 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 2200000 reads
26:34:09.822 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 4200000 reads
26:34:12.526 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 8400000 reads
26:34:29.791 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 16800000 reads
26:34:54.145 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 33600000 reads
26:35:42.074 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 67200000 reads
26:37:13.727 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 134400000 reads
26:40:25.544 61G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 268506167 reads
26:41:10.594 61G / 311G INFO General (sequence_mapper_notifier.h: 100) Total 295374451 reads processed
26:41:12.071 61G / 311G INFO General (pair_info_count.cpp : 134) Edge pairs: 778839659
26:41:12.071 61G / 311G INFO General (pair_info_count.cpp : 138) 113213053 paired reads (38.3287% of all) aligned to long edges
26:41:12.316 59G / 311G INFO General (pair_info_count.cpp : 334) Insert size = 322.345, deviation = 91.077, left quantile = 201, right quantile = 439, read length = 150
26:41:13.120 62G / 311G INFO General (pair_info_count.cpp : 351) Filtering data for library #0
26:41:13.130 62G / 311G INFO General (short_read_mapper.hpp : 88) Selecting usual mapper
26:41:39.789 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 200000 reads
26:41:39.869 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 400000 reads
26:41:40.783 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 600000 reads
26:41:41.453 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 800000 reads
26:41:41.490 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 1000000 reads
26:41:41.887 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 1200000 reads
26:41:42.570 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 2200000 reads
26:41:47.264 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 4200000 reads
26:41:51.191 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 8400000 reads
26:42:06.358 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 16800000 reads
26:42:37.475 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 33600000 reads
26:43:42.570 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 67200000 reads
26:45:58.942 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 134400000 reads
26:50:09.750 62G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 268443612 reads
26:51:25.100 62G / 311G INFO General (sequence_mapper_notifier.h: 100) Total 295374451 reads processed
26:51:25.102 62G / 311G INFO General (pair_info_count.cpp : 363) Mapping library #0
26:51:25.103 62G / 311G INFO General (pair_info_count.cpp : 365) Mapping paired reads (takes a while)
26:51:25.103 62G / 311G INFO General (pair_info_count.cpp : 204) Left insert size quantile 201, right insert size quantile 439, filtering threshold 2, rounding threshold 0
26:51:25.129 62G / 311G INFO General (short_read_mapper.hpp : 88) Selecting usual mapper
26:53:29.703 74G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 200000 reads
26:53:30.500 74G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 400000 reads
26:53:31.485 74G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 600000 reads
26:53:32.937 74G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 800000 reads
26:53:33.487 74G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 1000000 reads
26:53:36.530 74G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 1200000 reads
26:53:41.212 74G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 2200000 reads
26:54:06.852 76G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 4200000 reads
26:54:17.704 77G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 8400000 reads
26:55:19.264 80G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 16800000 reads
26:57:26.945 86G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 33600000 reads
27:03:07.849 97G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 67200000 reads
27:13:46.833 113G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 134400000 reads
27:33:09.810 136G / 311G INFO General (sequence_mapper_notifier.h: 82) Processed 268506166 reads
27:37:03.029 139G / 311G INFO General (sequence_mapper_notifier.h: 100) Total 295374451 reads processed
27:37:06.067 137G / 311G INFO General (pair_info_count.cpp : 304) Library #1 was mapped earlier on hybrid aligning stage, skipping
27:37:06.067 137G / 311G INFO StageManager (stage.cpp : 126) STAGE == Distance Estimation
27:37:06.067 137G / 311G INFO General (distance_estimation.cpp : 224) Processing library #0
27:37:06.067 137G / 311G INFO General (distance_estimation.cpp : 130) Weight Filter Done
27:37:06.067 137G / 311G INFO DistanceEstimator (distance_estimation.hpp : 176) Using SIMPLE distance estimator
29:04:15.105 168G / 311G INFO General (distance_estimation.cpp : 35) Filtering info
29:04:15.105 168G / 311G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 1493814653
29:17:08.753 182G / 311G INFO General (pair_info_filters.hpp : 263) Done filtering
29:17:10.698 166G / 311G INFO General (distance_estimation.cpp : 172) Refining clustered pair information
29:21:41.072 166G / 311G INFO General (distance_estimation.cpp : 174) The refining of clustered pair information has been finished
29:21:41.073 166G / 311G INFO General (distance_estimation.cpp : 176) Improving paired information
30:14:41.592 175G / 311G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 115096670; contradictional = 69176
31:18:16.162 179G / 311G INFO PairInfoImprover (pair_info_improver.hpp : 103) Paired info stats: missing = 28019533; contradictional = 700
31:18:16.163 179G / 311G INFO General (distance_estimation.cpp : 183) Filling scaffolding index
31:18:16.163 179G / 311G INFO DistanceEstimator (distance_estimation.hpp : 176) Using SMOOTHING distance estimator
32:28:34.225 184G / 311G INFO General (distance_estimation.cpp : 35) Filtering info
32:28:34.225 184G / 311G INFO General (pair_info_filters.hpp : 242) Start filtering; index size: 127166363
32:29:39.609 188G / 311G INFO General (pair_info_filters.hpp : 263) Done filtering
32:29:40.116 184G / 311G INFO General (distance_estimation.cpp : 228) Clearing raw paired index
32:42:20.570 107G / 311G INFO StageManager (stage.cpp : 126) STAGE == Repeat Resolving
32:42:20.570 107G / 311G INFO General (repeat_resolving.cpp : 68) Using Path-Extend repeat resolving
32:42:45.584 107G / 311G INFO General (launcher.cpp : 399) ExSPAnder repeat resolving tool started
32:42:45.588 107G / 311G INFO General (launcher.cpp : 169) Autodetecting unique edge set parameters...
32:42:45.588 107G / 311G INFO General (launcher.cpp : 171) Minimal unique edge length set to the smallest MP library IS: 2000
32:42:47.112 107G / 311G INFO General (coverage_uniformity_analyz: 31) genomic coverage is 73.7417 calculated of length 156441194
32:42:48.612 107G / 311G INFO General (launcher.cpp : 177) median coverage for edges longer than 2000 is 73.7417 uniformity 89%
32:42:52.332 107G / 311G INFO ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 56) With length cutoff: 2000, median long edge coverage: 73.7418, and maximal unique coverage: 0.5
32:42:52.332 107G / 311G INFO ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 57) Unique edges quantity: 66526, unique edges length 279024938, total edges length 1086572447
32:42:52.332 107G / 311G WARN ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 59) Less than half of genome in unique edges!
32:43:41.627 121G / 311G INFO General (launcher.cpp : 357) Creating main extenders, unique edge length = 2000
32:43:43.616 121G / 311G INFO General (extenders_logic.cpp : 251) Estimated coverage of library #0 is 73.8357
32:43:44.560 121G / 311G INFO General (extenders_logic.cpp : 251) Estimated coverage of library #0 is 73.8357
32:43:49.356 121G / 311G INFO General (extenders_logic.cpp : 33) resolvable_repeat_length_bound set to 10000
32:44:11.168 121G / 311G INFO General (extenders_logic.cpp : 415) Using 1 paired-end library
32:44:11.168 121G / 311G INFO General (extenders_logic.cpp : 416) Using 1 paired-end scaffolding library
32:44:11.168 121G / 311G INFO General (extenders_logic.cpp : 417) Using 1 single read library
32:44:13.452 121G / 311G INFO General (launcher.cpp : 324) Filling backbone edges for long reads scaffolding...
32:44:13.452 121G / 311G INFO General (launcher.cpp : 343) with coverage
32:44:15.578 121G / 311G INFO ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 56) With length cutoff: 500, median long edge coverage: 70.9028, and maximal unique coverage: 0.5
32:44:15.578 121G / 311G INFO ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 57) Unique edges quantity: 303700, unique edges length 507851564, total edges length 1086572447
32:44:15.578 121G / 311G WARN ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 59) Less than half of genome in unique edges!
32:44:15.578 121G / 311G INFO General (launcher.cpp : 346) 303700 unique edges
32:44:15.578 121G / 311G INFO General (extenders_logic.cpp : 312) Creating scaffolding extender for lib 1
32:44:15.611 121G / 311G INFO ExtensionChooser2015 (extension_chooser2015.hpp : 51) ExtensionChooser2015 created
32:44:18.973 121G / 311G INFO General (extenders_logic.cpp : 336) Using 1 long reads scaffolding library
32:44:18.973 121G / 311G INFO General (launcher.cpp : 385) Total number of extenders is 5
32:44:18.973 121G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 0 paths from 3343810 (0%)
32:44:26.176 121G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 128 paths from 3343810 (0%)
32:45:08.745 121G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 256 paths from 3343810 (0%)
32:46:48.146 121G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 512 paths from 3343810 (0%)
32:48:50.745 121G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 1024 paths from 3343810 (0%)
32:51:23.311 121G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 2048 paths from 3343810 (0%)
32:56:57.026 121G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 4096 paths from 3343810 (0%)
33:04:06.972 121G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 8192 paths from 3343810 (0%)
33:09:51.475 122G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 16384 paths from 3343810 (0%)
33:13:15.972 122G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 32768 paths from 3343810 (0%)
33:16:32.691 122G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 65536 paths from 3343810 (1%)
33:20:59.079 122G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 131072 paths from 3343810 (3%)
33:27:26.155 123G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 262144 paths from 3343810 (7%)
33:30:36.287 124G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 334382 paths from 3343810 (10%)
33:39:09.225 125G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 524288 paths from 3343810 (15%)
33:44:02.694 126G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 668764 paths from 3343810 (20%)
34:00:18.837 128G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 1003146 paths from 3343810 (30%)
34:02:54.765 128G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 1048576 paths from 3343810 (31%)
34:27:30.784 130G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 1337528 paths from 3343810 (40%)
34:42:54.144 132G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 1671910 paths from 3343810 (50%)
34:49:15.128 132G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 2006292 paths from 3343810 (60%)
34:50:11.943 132G / 311G INFO PathExtender (path_extender.hpp :1029) Processed 2097152 paths from 3343810 (62%)
34:52:34.729 132G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 2340674 paths from 3343810 (70%)
34:54:34.327 132G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 2675056 paths from 3343810 (80%)
34:55:38.152 132G / 311G INFO PathExtender (path_extender.hpp :1031) Processed 3009438 paths from 3343810 (90%)
35:06:42.080 133G / 311G INFO General (launcher.cpp : 248) Traversing tandem repeats
35:08:26.998 133G / 311G INFO General (launcher.cpp : 258) Traversed 6482 loops
35:08:26.998 133G / 311G INFO General (launcher.cpp : 391) Closing gaps in paths
35:10:41.788 139G / 311G INFO General (launcher.cpp : 395) Gap closing completed
35:13:43.190 140G / 311G INFO General (launcher.cpp : 445) ExSPAnder repeat resolving tool finished
35:15:30.190 116G / 311G INFO StageManager (stage.cpp : 126) STAGE == Contig Output
35:15:30.190 116G / 311G INFO General (contig_output.hpp : 478) Outputting contigs to /dat1/Rose_Denovo/resf/spade/ass4//K77/before_rr.fasta
35:16:14.993 116G / 311G INFO General (contig_output.hpp : 518) Outputting graph to /dat1/Rose_Denovo/resf/spade/ass4//K77/assembly_graph.fastg
35:19:27.457 120G / 311G INFO PathExtendIO (bidirectional_path_output.: 31) Writing contigs to /dat1/Rose_Denovo/resf/spade/ass4//K77/final_contigs
35:20:50.321 117G / 311G INFO PathExtendIO (bidirectional_path_output.: 31) Writing contigs to /dat1/Rose_Denovo/resf/spade/ass4//K77/scaffolds
35:21:48.394 116G / 311G INFO General (contig_output.hpp : 509) Outputting graph to /dat1/Rose_Denovo/resf/spade/ass4//K77/assembly_graph.gfa
35:22:56.659 116G / 311G INFO General (launch.hpp : 136) SPAdes finished
35:32:54.933 8G / 311G INFO General (main.cpp : 109) Assembling time: 35 hours 32 minutes 54 seconds
===== Assembling finished. Used k-mer sizes: 21, 33, 55, 77
* Corrected reads are in /dat1/Rose_Denovo/resf/spade/ass4/corrected/
* Assembled contigs are in /dat1/Rose_Denovo/resf/spade/ass4/contigs.fasta
* Assembled scaffolds are in /dat1/Rose_Denovo/resf/spade/ass4/scaffolds.fasta
* Assembly graph is in /dat1/Rose_Denovo/resf/spade/ass4/assembly_graph.fastg
* Assembly graph in GFA format is in /dat1/Rose_Denovo/resf/spade/ass4/assembly_graph.gfa
* Paths in the assembly graph corresponding to the contigs are in /dat1/Rose_Denovo/resf/spade/ass4/contigs.paths
* Paths in the assembly graph corresponding to the scaffolds are in /dat1/Rose_Denovo/resf/spade/ass4/scaffolds.paths
======= SPAdes pipeline finished WITH WARNINGS!
=== Error correction and assembling warnings:
* 32:42:52.332 107G / 311G WARN ScaffoldingUniqueEdgeAna (scaff_supplementary.cpp : 59) Less than half of genome in unique edges!
======= Warnings saved to /dat1/Rose_Denovo/resf/spade/ass4/warnings.log
SPAdes log can be found here: /dat1/Rose_Denovo/resf/spade/ass4/spades.log
Thank you for using SPAdes!Thanks!
asl
commented
7 years ago The warning is benign. You're having a dataset with not so small genome (~60 Mbp) and therefore the graph contains not that much long contigs. The warning is perfectly expected in this case. As for the size of the largest contig - I would say it's ok given the size of the genome and the properties of the input dataset (only single 150bp paired-end library with short fragment length + pacbio).
Hi, I use spades for hybrid assemble with illumina reads and Pacbio Sequel reads. It reports the warnings as below:
And the result show the longest scaffolds in the scaffolds.fasta file only 70kb. Below is the command I used: