spades icon indicating copy to clipboard operation
spades copied to clipboard
verified publisher icon ablab

mimalloc error

Open rishidash12 opened this issue 6 months ago • 1 comments

Description of bug

I have run metaSPAdes for the assembly of metagenomic data across 160 samples. While the assembly completed successfully for most samples, I encountered a mimalloc error in 7 of them. To troubleshoot, I tried increasing the available RAM, but the issue persisted. I also attempted to limit the assembly to a single k-mer size (k=55), yet the error still occurred for the same samples. For your reference, I have attached the spades.log file and the params.txt file from one of the affected runs. I would greatly appreciate your assistance in identifying the cause of this error and suggesting potential solutions.

spades.log

Command line: /home/bala/.conda/envs/myenv/bin/metaspades.py --12 /home/bala/AIIMS/fastq/NEMO321_V1.fastq -o /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out --only-assembler -k 55

System information: SPAdes version: 4.2.0 Python version: 3.13.2 OS: Linux-4.18.0-513.9.1.el8_9.x86_64-x86_64-with-glibc2.28

Output dir: /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out Mode: ONLY assembling (without read error correction) Debug mode is turned OFF

Dataset parameters: Metagenomic mode Reads: Library number: 1, library type: paired-end orientation: fr left reads: not specified right reads: not specified interlaced reads: ['/home/bala/AIIMS/fastq/NEMO321_V1.fastq'] single reads: not specified merged reads: not specified Assembly parameters: k: [55] Repeat resolution is enabled Mismatch careful mode is turned OFF MismatchCorrector will be SKIPPED Coverage cutoff is turned OFF Assembly graph output will use GFA v1.2 format Other parameters: Dir for temp files: /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/tmp Threads: 16 Memory limit (in Gb): 250

======= SPAdes pipeline started. Log can be found here: /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/spades.log

/home/bala/AIIMS/fastq/NEMO321_V1.fastq: max reads length: 151

Reads length: 151

===== Before start started.

===== Preprocess reads started.

===== Preprocess reads finished.

===== Assembling started.

===== K55 started.

== Running: /home/bala/.conda/envs/myenv/bin/spades-core /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/config.info /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/mda_mode.info /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/meta_mode.info

0:00:00.000 1M / 25M INFO General (main.cpp : 94) Loaded config from "/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/config.info" 0:00:00.026 1M / 25M INFO General (main.cpp : 94) Loaded config from "/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/mda_mode.info" 0:00:00.045 1M / 25M INFO General (main.cpp : 94) Loaded config from "/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/meta_mode.info" 0:00:00.060 1M / 25M INFO General (memory_limit.cpp : 55) Memory limit set to 250 Gb 0:00:00.071 1M / 25M INFO General (main.cpp : 102) Starting SPAdes, built from N/A, git revision N/A 0:00:00.082 1M / 25M INFO General (main.cpp : 103) Maximum k-mer length: 128 0:00:00.093 1M / 25M INFO General (main.cpp : 104) Assembling dataset ("/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/dataset.info") with K=55 0:00:00.104 1M / 25M INFO General (main.cpp : 105) Maximum # of threads to use (adjusted due to OMP capabilities): 16 0:00:00.115 1M / 25M INFO General (pipeline.cpp : 221) SPAdes started 0:00:00.120 1M / 25M INFO General (pipeline.cpp : 234) Starting from stage: read_conversion 0:00:00.131 1M / 25M INFO General (pipeline.cpp : 245) Two-step repeat resolution enabled 0:00:00.142 1M / 25M INFO GraphCore (graph_core.hpp : 689) Graph created, vertex min_id: 3, edge min_id: 3 0:00:00.153 1M / 25M INFO GraphCore (graph_core.hpp : 690) Vertex size: 48, edge size: 40 0:00:00.163 1M / 25M INFO General (edge_index.hpp : 132) Size of edge index entries: 12/8 0:00:00.174 1M / 25M INFO General (pipeline.cpp : 256) Will need read mapping, kmer mapper will be attached 0:00:00.185 1M / 25M INFO StageManager (stage.cpp : 212) STAGE == Binary Read Conversion (id: read_conversion) 0:00:00.197 1M / 25M INFO General (read_converter.cpp : 78) Converting reads to binary format for library #0 (takes a while) 0:00:00.209 1M / 25M INFO General (read_converter.cpp : 99) Converting paired reads 0:00:00.390 55M / 73M INFO General (binary_converter.cpp : 127) 16384 reads processed 0:00:00.414 55M / 80M INFO General (binary_converter.cpp : 127) 32768 reads processed 0:00:00.471 55M / 97M INFO General (binary_converter.cpp : 127) 65536 reads processed 0:00:00.550 55M / 113M INFO General (binary_converter.cpp : 127) 131072 reads processed 0:00:00.781 11M / 161M INFO General (binary_converter.cpp : 127) 262144 reads processed 0:00:01.161 0M / 218M INFO General (binary_converter.cpp : 127) 524288 reads processed 0:00:01.939 0M / 301M INFO General (binary_converter.cpp : 127) 1048576 reads processed 0:00:03.635 0M / 345M INFO General (binary_converter.cpp : 127) 2097152 reads processed 0:00:06.912 0M / 390M INFO General (binary_converter.cpp : 127) 4194304 reads processed 0:00:13.489 0M / 465M INFO General (binary_converter.cpp : 127) 8388608 reads processed 0:00:27.037 0M / 589M INFO General (binary_converter.cpp : 127) 16777216 reads processed 0:00:43.304 0M / 628M INFO General (binary_converter.cpp : 143) 27058031 reads written 0:00:43.322 0M / 628M INFO General (read_converter.cpp : 113) Converting single reads 0:00:43.334 0M / 628M INFO General (binary_converter.cpp : 143) 0 reads written 0:00:43.345 0M / 628M INFO General (read_converter.cpp : 119) Converting merged reads 0:00:43.357 0M / 628M INFO General (binary_converter.cpp : 143) 0 reads written 0:00:43.396 1M / 628M INFO StageManager (stage.cpp : 212) STAGE == de Bruijn graph construction (id: construction) 0:00:43.412 1M / 628M INFO General (construction.cpp : 150) Max read length 151 0:00:43.423 1M / 628M INFO General (construction.cpp : 156) Average read length 137.482 0:00:43.434 1M / 628M INFO General (stage.cpp : 121) PROCEDURE == k+1-mer counting (id: construction:kpomer_counting) 0:00:43.445 1M / 628M INFO General (kmer_index_builder.hpp : 308) Splitting kmer instances into 160 files using 16 threads. This might take a while. 0:00:43.495 1M / 628M INFO General (file_limit.hpp : 43) Open file limit set to 1024 0:00:43.523 1M / 628M INFO General (kmer_splitter.hpp : 96) Memory available for splitting buffers: 5.20833 Gb 0:00:43.534 1M / 628M INFO General (kmer_splitter.hpp : 104) Using cell size of 209715 0:00:50.449 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 11318468 reads 0:00:56.995 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 22255267 reads 0:01:03.584 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 33031461 reads 0:01:10.176 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 43744952 reads 0:01:16.955 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 54559133 reads 0:01:23.714 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 65273751 reads 0:01:30.232 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 76165668 reads 0:01:36.736 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 87335991 reads 0:01:43.205 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 98433249 reads 0:01:48.354 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 106894079 reads 0:01:49.491 9601M / 11G INFO General (kmer_splitters.hpp : 128) Processed 108232124 reads 0:01:49.508 1M / 11G INFO General (kmer_splitters.hpp : 134) Used 108232124 reads 0:01:49.525 1M / 11G INFO General (kmer_index_builder.hpp : 314) Starting k-mer counting. 0:01:54.805 1M / 11G INFO General (kmer_index_builder.hpp : 325) K-mer counting done. There are 804384584 kmers in total. 0:01:54.815 1M / 11G INFO General (stage.cpp : 121) PROCEDURE == Extension index construction (id: construction:extension_index_construction) 0:01:54.840 1M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 503) Building kmer index 0:01:54.846 1M / 11G INFO General (kmer_index_builder.hpp : 308) Splitting kmer instances into 160 files using 16 threads. This might take a while. 0:01:54.895 2M / 11G INFO General (file_limit.hpp : 43) Open file limit set to 1024 0:01:54.917 2M / 11G INFO General (kmer_splitter.hpp : 96) Memory available for splitting buffers: 5.20831 Gb 0:01:54.928 2M / 11G INFO General (kmer_splitter.hpp : 104) Using cell size of 209715 0:01:55.881 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 8761721 kmers 0:01:56.323 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 18522952 kmers 0:01:56.817 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 30529316 kmers 0:01:57.261 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 41101647 kmers 0:01:57.758 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 50184297 kmers 0:01:58.314 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 61561057 kmers 0:01:58.770 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 73201918 kmers 0:01:59.383 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 88939012 kmers 0:01:59.859 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 98739941 kmers 0:02:00.347 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 110720546 kmers 0:02:00.833 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 121343566 kmers 0:02:01.309 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 130542852 kmers 0:02:01.849 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 141745436 kmers 0:02:02.348 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 153575299 kmers 0:02:02.978 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 169392282 kmers 0:02:03.415 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 179183724 kmers 0:02:03.908 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 191161977 kmers 0:02:04.430 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 201777268 kmers 0:02:07.460 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 271626295 kmers 0:02:19.382 9602M / 11G INFO General (kmer_splitters.hpp : 197) Processed 543944565 kmers 0:02:34.328 9602M / 11G INFO General (kmer_splitters.hpp : 202) Used 804390744 kmers. 0:02:34.347 2M / 11G INFO General (kmer_index_builder.hpp : 314) Starting k-mer counting. 0:02:46.155 2M / 11G INFO General (kmer_index_builder.hpp : 325) K-mer counting done. There are 789788369 kmers in total. 0:02:46.161 2M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 460) Building perfect hash indices 0:03:08.186 581M / 11G INFO K-mer Index Building (kmer_index_builder.hpp : 496) Index built. Total 789788369 kmers, 570552832 bytes occupied (5.7793 bits per kmer). 0:03:08.197 581M / 11G INFO General (kmer_index_builder.hpp : 191) Merging final buckets. 0:03:16.938 1337M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 101) Building k-mer extensions from k+1-mers 0:04:29.055 1337M / 11G INFO DeBruijnExtensionIndexBu (kmer_extension_index_build: 106) Building k-mer extensions from k+1-mers finished. 0:04:29.143 1336M / 11G INFO General (stage.cpp : 121) PROCEDURE == Condensing graph (id: construction:graph_condensing) 0:04:29.156 1337M / 11G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 324) Extracting unbranching paths 0:06:13.479 3925M / 17G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 348) Extracting unbranching paths finished. 54750341 sequences extracted 0:07:02.329 3925M / 18G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 362) Collecting perfect loops 0:07:26.629 3925M / 18G INFO UnbranchingPathExtractor (debruijn_graph_constructor: 395) Collecting perfect loops finished. 0 loops collected 0:07:27.456 3925M / 18G INFO DeBruijnGraphConstructor (debruijn_graph_constructor: 593) Sorting edges... 0:07:31.139 3925M / 18G INFO DeBruijnGraphConstructor (debruijn_graph_constructor: 598) Edges sorted 0:07:31.155 3925M / 18G INFO General (debruijn_graph_constructor: 511) Total 109500682 edges to create mimalloc: warning: unable to allocate aligned OS memory directly, fall back to over-allocation (4408213504 bytes, address: 0x7f2d6656f000, alignment: 67108864, commit: 1) 0:07:31.173 8139M / 18G INFO General (debruijn_graph_constructor: 514) Collecting link records mimalloc: warning: unable to allocate aligned OS memory directly, fall back to over-allocation (1757413376 bytes, address: 0x7f2cfb400000, alignment: 67108864, commit: 1) 0:07:41.552 10G / 18G INFO General (debruijn_graph_constructor: 519) Ordering link records 0:07:44.123 10G / 18G INFO General (debruijn_graph_constructor: 525) Sorting done 0:07:44.517 11G / 18G INFO General (debruijn_graph_constructor: 538) Sorting LinkRecords... 0:07:46.462 11G / 18G INFO General (debruijn_graph_constructor: 544) LinkRecords sorted 0:07:46.474 11G / 18G INFO General (debruijn_graph_constructor: 546) Total 40154126 vertices to create mimalloc: warning: unable to allocate aligned OS memory directly, fall back to over-allocation (3879731200 bytes, address: 0x7f2c10c00000, alignment: 67108864, commit: 1) 0:07:46.486 14G / 18G INFO General (debruijn_graph_constructor: 549) Connecting the graph 0:08:01.736 11G / 18G INFO General (stage.cpp : 121) PROCEDURE == Filling coverage indices (PHM) (id: construction:coverage_filling_phm) 0:08:01.747 11G / 18G INFO K-mer Index Building (kmer_index_builder.hpp : 460) Building perfect hash indices 0:08:24.305 12G / 18G INFO K-mer Index Building (kmer_index_builder.hpp : 496) Index built. Total 804384584 kmers, 581095760 bytes occupied (5.77928 bits per kmer). mimalloc: warning: unable to allocate aligned OS memory directly, fall back to over-allocation (3225419776 bytes, address: 0x7f2b4fc00000, alignment: 67108864, commit: 1) 0:08:24.722 15G / 18G INFO General (coverage_hash_map_builder.: 49) Collecting k-mer coverage information from reads, this takes a while. 0:11:02.372 15G / 18G INFO General (construction.cpp : 400) Filling coverage and flanking coverage from PHM 0:11:15.973 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 16000000 edges 0:11:29.519 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 32000000 edges 0:11:41.534 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 47158279 edges 0:11:50.886 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 60451111 edges 0:11:59.619 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 73484677 edges 0:12:08.077 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 85828073 edges 0:12:15.490 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 95820242 edges 0:12:20.397 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 102502402 edges 0:12:23.908 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 107221430 edges 0:12:25.379 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 108858240 edges 0:12:26.069 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 109333066 edges 0:12:26.555 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 109438794 edges 0:12:26.859 15G / 18G INFO General (coverage_filling.hpp : 83) Processed 109500677 edges 0:12:30.676 10G / 18G INFO StageManager (stage.cpp : 212) STAGE == Gap Closer (id: early_gapcloser) 0:12:30.692 10G / 18G INFO General (edge_index.hpp : 132) Size of edge index entries: 12/8 0:12:33.326 10G / 18G INFO General (gap_closer.cpp : 117) Total edges in tip neighborhood: 11204307 out of 109500677, length: 258075982 0:12:33.865 10G / 18G INFO General (edge_index.hpp : 196) Using small index (max_id = 110048188) 0:12:35.561 10G / 18G INFO K-mer Index Building (kmer_index_builder.hpp : 460) Building perfect hash indices 0:12:57.956 11G / 18G INFO K-mer Index Building (kmer_index_builder.hpp : 496) Index built. Total 241656685 kmers, 174540696 bytes occupied (5.77814 bits per kmer). mimalloc: warning: unable to allocate aligned OS memory directly, fall back to over-allocation (1937768448 bytes, address: 0x7f2b9c800000, alignment: 67108864, commit: 1) 0:12:58.244 12G / 18G INFO General (edge_index_builders.hpp : 266) Collecting edge information from graph, this takes a while. 0:13:09.036 12G / 18G INFO General (sequence_mapper_notifier.h: 80) Starting sequence mapping 0:13:22.323 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 200000 reads 0:13:27.565 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 400000 reads 0:13:30.147 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 600000 reads 0:13:30.957 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 800000 reads 0:13:31.222 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 1000000 reads 0:13:31.321 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 1200000 reads 0:13:38.393 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 2200000 reads 0:13:57.878 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 4200000 reads 0:14:33.293 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 8400000 reads 0:15:42.567 12G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 16800000 reads 0:17:03.630 13G / 18G INFO General (sequence_mapper_notifier.h: 120) Total 27058031 reads processed 0:17:06.886 11G / 18G INFO General (gap_closer.cpp : 505) Initializing gap closer 0:17:06.925 11G / 18G INFO GapCloser (gap_closer.cpp : 421) Collecting gap candidates 0:17:09.485 11G / 18G INFO GapCloser (gap_closer.cpp : 425) Total 157648 tips collected, total 165082 connection candidates 0:17:09.797 11G / 18G INFO GapCloser (gap_closer.cpp : 446) Closing short gaps complete: filled 1385 gaps after checking 163662 candidates 0:17:10.332 11G / 18G INFO General (gap_closer.cpp : 510) Gap closer done 0:17:10.736 10G / 18G INFO StageManager (stage.cpp : 212) STAGE == Raw Simplification (id: raw_simplification) 0:17:10.748 10G / 18G INFO General (simplification.cpp : 129) PROCEDURE == Initial cleaning 0:17:10.759 10G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Self conjugate edge remover 0:17:11.641 10G / 18G INFO Simplification (parallel_processing.hpp : 171) Self conjugate edge remover triggered 0 times 0:17:11.652 10G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Initial tip clipper 0:17:42.001 10G / 18G INFO Simplification (parallel_processing.hpp : 171) Initial tip clipper triggered 6532268 times 0:17:42.103 10G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Initial ec remover 0:17:44.212 10G / 18G INFO Simplification (parallel_processing.hpp : 171) Initial ec remover triggered 146 times 0:17:44.228 10G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Disconnecting edges with low flanking coverage 0:17:45.383 10G / 18G INFO Simplification (parallel_processing.hpp : 171) Disconnecting edges with low flanking coverage triggered 258 times 0:17:45.389 10G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Initial isolated edge remover 0:17:46.879 10G / 18G INFO Simplification (parallel_processing.hpp : 171) Initial isolated edge remover triggered 389110 times 0:17:46.900 9410M / 18G INFO StageManager (stage.cpp : 212) STAGE == Preliminary Simplification (id: simplification_preliminary) 0:17:46.913 9410M / 18G INFO General (simplification.cpp : 397) Graph simplification started 0:17:46.924 9410M / 18G INFO General (graph_simplification.hpp : 646) Creating parallel br instance 0:17:46.935 9410M / 18G INFO General (simplification.cpp : 402) PROCEDURE == Simplification cycle, iteration 1 0:17:46.946 9410M / 18G INFO Simplification (parallel_processing.hpp : 168) Running Tip clipper 0:17:59.814 9346M / 18G INFO Simplification (parallel_processing.hpp : 171) Tip clipper triggered 3557848 times 0:18:00.000 9346M / 18G INFO Simplification (parallel_processing.hpp : 168) Running Bulge remover 0:21:31.791 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Bulge remover triggered 352983 times 0:21:31.814 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Low coverage edge remover 0:21:35.818 13G / 18G INFO Simplification (parallel_processing.hpp : 171) Low coverage edge remover triggered 0 times 0:21:35.833 13G / 18G INFO General (simplification.cpp : 402) PROCEDURE == Simplification cycle, iteration 2 0:21:35.847 13G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Tip clipper 0:21:38.018 13G / 18G INFO Simplification (parallel_processing.hpp : 171) Tip clipper triggered 16650 times 0:21:38.033 13G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Bulge remover 0:21:38.302 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Bulge remover triggered 145 times 0:21:38.323 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Low coverage edge remover 0:22:31.199 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Low coverage edge remover triggered 8138667 times 0:22:31.627 12G / 18G INFO General (simplification.cpp : 402) PROCEDURE == Simplification cycle, iteration 3 0:22:31.649 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Tip clipper 0:22:35.288 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Tip clipper triggered 64316 times 0:22:35.304 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Bulge remover 0:23:17.919 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Bulge remover triggered 41415 times 0:23:18.003 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Low coverage edge remover 0:23:31.857 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Low coverage edge remover triggered 2123122 times 0:23:32.054 12G / 18G INFO General (simplification.cpp : 402) PROCEDURE == Simplification cycle, iteration 4 0:23:32.069 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Tip clipper 0:23:32.765 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Tip clipper triggered 8717 times 0:23:32.775 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Bulge remover 0:24:04.027 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Bulge remover triggered 6209 times 0:24:04.054 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Low coverage edge remover 0:24:04.604 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Low coverage edge remover triggered 276 times 0:24:04.613 12G / 18G INFO General (simplification.cpp : 402) PROCEDURE == Simplification cycle, iteration 5 0:24:04.624 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Tip clipper 0:24:04.720 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Tip clipper triggered 31 times 0:24:04.726 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Bulge remover 0:24:04.756 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Bulge remover triggered 0 times 0:24:04.761 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Low coverage edge remover 0:24:04.772 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Low coverage edge remover triggered 0 times 0:24:04.783 12G / 18G INFO General (simplification.cpp : 402) PROCEDURE == Simplification cycle, iteration 6 0:24:04.794 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Tip clipper 0:24:04.805 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Tip clipper triggered 0 times 0:24:04.816 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Bulge remover 0:24:04.826 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Bulge remover triggered 0 times 0:24:04.837 12G / 18G INFO Simplification (parallel_processing.hpp : 168) Running Low coverage edge remover 0:24:04.848 12G / 18G INFO Simplification (parallel_processing.hpp : 171) Low coverage edge remover triggered 0 times 0:24:05.232 11G / 18G INFO StageManager (stage.cpp : 212) STAGE == Gap Closer (id: prelim_gapcloser) 0:24:05.254 11G / 18G INFO General (edge_index.hpp : 132) Size of edge index entries: 12/8 0:24:05.656 11G / 18G INFO General (gap_closer.cpp : 117) Total edges in tip neighborhood: 47001 out of 20791096, length: 6526756 0:24:05.670 11G / 18G INFO General (edge_index.hpp : 196) Using small index (max_id = 110048188) 0:24:05.706 11G / 18G INFO K-mer Index Building (kmer_index_builder.hpp : 460) Building perfect hash indices 0:24:06.120 11G / 18G INFO K-mer Index Building (kmer_index_builder.hpp : 496) Index built. Total 4800458 kmers, 3467936 bytes occupied (5.77934 bits per kmer). 0:24:06.142 11G / 18G INFO General (edge_index_builders.hpp : 266) Collecting edge information from graph, this takes a while. 0:24:06.232 11G / 18G INFO General (sequence_mapper_notifier.h: 80) Starting sequence mapping 0:24:22.037 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 200000 reads 0:24:22.178 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 400000 reads 0:24:22.201 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 600000 reads 0:24:22.231 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 800000 reads 0:24:22.931 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 1000000 reads 0:24:24.281 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 1200000 reads 0:24:25.954 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 2200000 reads 0:24:38.208 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 4200000 reads 0:24:55.948 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 8400000 reads 0:25:36.676 11G / 18G INFO General (sequence_mapper_notifier.h: 101) Processed 16800000 reads 0:26:33.412 11G / 18G INFO General (sequence_mapper_notifier.h: 120) Total 27058031 reads processed 0:26:33.437 11G / 18G INFO General (gap_closer.cpp : 505) Initializing gap closer 0:26:33.443 11G / 18G INFO GapCloser (gap_closer.cpp : 421) Collecting gap candidates 0:26:34.089 11G / 18G INFO GapCloser (gap_closer.cpp : 425) Total 2330 tips collected, total 9115 connection candidates 0:26:34.102 11G / 18G INFO GapCloser (gap_closer.cpp : 446) Closing short gaps complete: filled 2 gaps after checking 9113 candidates 0:26:34.475 11G / 18G INFO General (gap_closer.cpp : 510) Gap closer done 0:26:34.484 11G / 18G INFO StageManager (stage.cpp : 212) STAGE == Preliminary Paired Information Counting (id: late_pair_info_count_preliminary) 0:26:46.129 19G / 21G INFO General (graph_pack_helpers.cpp : 44) Index refill 0:26:46.137 19G / 21G INFO General (edge_index.hpp : 175) Using small index (max_id = 110048188) 0:26:47.344 19G / 21G INFO K-mer Index Building (kmer_index_builder.hpp : 460) Building perfect hash indices 0:27:01.955 19G / 21G INFO K-mer Index Building (kmer_index_builder.hpp : 496) Index built. Total 200959574 kmers, 145152360 bytes occupied (5.77837 bits per kmer). mimalloc: warning: unable to allocate aligned OS memory directly, fall back to over-allocation (1614807040 bytes, address: 0x7f2d03c00000, alignment: 67108864, commit: 1) 0:27:02.198 20G / 23G INFO General (edge_index_builders.hpp : 253) Collecting edge information from graph, this takes a while. 0:27:07.656 20G / 23G INFO General (graph_pack_helpers.cpp : 54) Normalizing k-mer map. Total 45290196 kmers to process 0:27:18.726 20G / 23G INFO General (kmer_mapper.hpp : 87) Total 325200 kmers with non-trivial roots 0:27:18.758 20G / 23G INFO General (graph_pack_helpers.cpp : 56) Normalizing done 0:27:18.765 20G / 23G INFO General (pair_info_count.cpp : 165) Min edge length for estimation: 900 0:27:18.771 20G / 23G INFO General (pair_info_count.cpp : 176) Estimating insert size for library #0 0:27:18.777 20G / 23G INFO General (pair_info_count.cpp : 41) Selecting usual mapper 0:27:18.783 20G / 23G INFO General (paired_info_utils.cpp : 102) Estimating insert size (takes a while) 0:27:18.815 21G / 23G INFO General (sequence_mapper_notifier.h: 80) Starting sequence mapping 0:27:31.021 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 200000 reads 0:27:33.588 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 400000 reads 0:27:36.890 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 600000 reads 0:27:37.675 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 800000 reads 0:27:41.618 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 1000000 reads 0:27:41.651 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 1200000 reads 0:27:42.961 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 2200000 reads 0:28:04.581 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 4200000 reads 0:28:29.677 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 8400000 reads 0:29:21.078 21G / 23G INFO General (sequence_mapper_notifier.h: 101) Processed 16800000 reads 0:30:41.964 21G / 23G INFO General (sequence_mapper_notifier.h: 120) Total 27058031 reads processed 0:30:42.159 21G / 23G INFO General (paired_info_utils.cpp : 119) Edge pairs: 4090960687 0:30:42.166 21G / 23G INFO General (paired_info_utils.cpp : 121) 335921 paired reads (1.24148% of all) aligned to long edges 0:30:42.173 20G / 23G INFO General (pair_info_count.cpp : 196) Insert size = 147.419, deviation = 38.3691, left quantile = 110, right quantile = 200, read length = 151 0:30:42.179 20G / 23G WARN General (pair_info_count.cpp : 203) Estimated mean insert size 147.419 is very small compared to read length 151 0:30:42.185 20G / 23G INFO General (pair_info_count.cpp : 211) Filtering data for library #0 0:30:42.191 20G / 23G INFO General (pair_info_count.cpp : 41) Selecting usual mapper 0:30:43.854 32G / 34G INFO General (sequence_mapper_notifier.h: 80) Starting sequence mapping 0:31:16.945 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 200000 reads 0:31:47.387 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 400000 reads 0:31:55.961 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 600000 reads 0:31:56.281 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 800000 reads 0:32:02.663 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 1000000 reads 0:32:04.941 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 1200000 reads 0:32:31.036 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 2200000 reads 0:33:20.115 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 4200000 reads 0:35:55.536 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 8400000 reads 0:39:44.685 32G / 34G INFO General (sequence_mapper_notifier.h: 101) Processed 16800000 reads 0:45:53.472 32G / 34G INFO General (sequence_mapper_notifier.h: 120) Total 27058031 reads processed 0:45:53.480 32G / 34G INFO General (pair_info_count.cpp : 216) Mapping library #0 0:45:53.487 32G / 34G INFO General (pair_info_count.cpp : 218) Mapping paired reads (takes a while) 0:45:53.493 32G / 34G INFO General (pair_info_count.cpp : 41) Selecting usual mapper 0:45:53.499 32G / 34G INFO General (paired_info_utils.cpp : 152) Left insert size quantile 110, right insert size quantile 200, filtering threshold 1, rounding threshold 0 0:45:53.507 32G / 34G INFO General (sequence_mapper_notifier.h: 80) Starting sequence mapping 0:48:28.065 34G / 81G INFO General (sequence_mapper_notifier.h: 101) Processed 200000 reads 0:48:38.323 38G / 83G INFO General (sequence_mapper_notifier.h: 101) Processed 400000 reads 0:51:03.113 43G / 113G INFO General (sequence_mapper_notifier.h: 101) Processed 600000 reads 0:51:07.659 49G / 113G INFO General (sequence_mapper_notifier.h: 101) Processed 800000 reads 0:51:37.782 54G / 119G INFO General (sequence_mapper_notifier.h: 101) Processed 1000000 reads 0:51:51.684 60G / 121G INFO General (sequence_mapper_notifier.h: 101) Processed 1200000 reads 0:52:34.636 67G / 129G INFO General (sequence_mapper_notifier.h: 101) Processed 2200000 reads 0:56:59.597 70G / 167G INFO General (sequence_mapper_notifier.h: 101) Processed 4200000 reads 1:06:09.521 82G / 227G INFO General (sequence_mapper_notifier.h: 101) Processed 8400000 reads mimalloc: error: thread 0x7f2e7a188700: unable to allocate OS memory (67108864 bytes, error code: 12 [Cannot allocate memory], address: (nil), large only: 0, allow large: 1) mimalloc: process info: elapsed: 4448.181 s process: user: 48946.325 s, system: 1141.833 s, faults: 35929678 rss: current: 274883993600, peak: 267640627200 commit: current: 274883993600, peak: 274883993600

== Error == system call for: "['/home/bala/.conda/envs/myenv/bin/spades-core', '/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/config.info', '/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/mda_mode.info', '/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/meta_mode.info']" finished abnormally, OS return value: -6 None

======= SPAdes pipeline finished abnormally and WITH WARNINGS!

=== Error correction and assembling warnings:

  • 0:30:42.179 20G / 23G WARN General (pair_info_count.cpp : 203) Estimated mean insert size 147.419 is very small compared to read length 151 ======= Warnings saved to /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/warnings.log

=== ERRORs:

  • system call for: "['/home/bala/.conda/envs/myenv/bin/spades-core', '/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/config.info', '/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/mda_mode.info', '/home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/K55/configs/meta_mode.info']" finished abnormally, OS return value: -6

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

SPAdes log can be found here: /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/spades.log

Thank you for using metaSPAdes! If you use it in your research, please cite:

Nurk, S., Meleshko, D., Korobeynikov, A. and Pevzner, P.A., 2017. metaSPAdes: a new versatile metagenomic assembler. Genome research, 27(5), pp.824-834. doi.org/10.1101/gr.213959.116

params.txt

Command line: /home/bala/.conda/envs/myenv/bin/metaspades.py --12 /home/bala/AIIMS/fastq/NEMO321_V1.fastq -o /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out --only-assembler -k 55

System information: SPAdes version: 4.2.0 Python version: 3.13.2 OS: Linux-4.18.0-513.9.1.el8_9.x86_64-x86_64-with-glibc2.28

Output dir: /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out Mode: ONLY assembling (without read error correction) Debug mode is turned OFF

Dataset parameters: Metagenomic mode Reads: Library number: 1, library type: paired-end orientation: fr left reads: not specified right reads: not specified interlaced reads: ['/home/bala/AIIMS/fastq/NEMO321_V1.fastq'] single reads: not specified merged reads: not specified Assembly parameters: k: [55] Repeat resolution is enabled Mismatch careful mode is turned OFF MismatchCorrector will be SKIPPED Coverage cutoff is turned OFF Assembly graph output will use GFA v1.2 format Other parameters: Dir for temp files: /home/bala/AIIMS/failed_sample_metaspades/NEMO321_V1.out/tmp Threads: 16 Memory limit (in Gb): 250

SPAdes version

4.2.0

Operating System

OS: Linux-4.18.0-513.9.1.el8_9.x86_64-x86_64-with-glibc2.28

Python Version

3.13.2

Method of SPAdes installation

conda

No errors reported in spades.log

  • [x] Yes

rishidash12 avatar Jun 06 '25 05:06 rishidash12

To troubleshoot, I tried increasing the available RAM

How have you did it?

asl avatar Jun 06 '25 05:06 asl