Unsure if this indicates memory leak in `splitHaplotype`

[SHuang-Broad]

I've been trying to build our cloud-native pipelines using trioCanu, and think this might be useful for the canu developers.

Show below is the resource usage during splitHaplotype.

Note that the memory usage "drifted" higher from the first to the last "hump"s. Is this expected? If unexpected, I'm not sure how high a priority this is for the team (not a high priority for us), but I think this might be useful in case you're interested in looking into it.

I've attached the shell script, the out file and the log below. Archive.zip

[brianwalenz]

Nice! I think this is expected.

The kmer database is split into 64 pieces, which can be loaded in parallel, one per thread. There are two databases to load - 128 total pieces - so four humps are expected when 36 threads are available. The first two humps should be the first database, the second two the second. The growth is hopefully just the kmers being loaded. Reasonably expected.

The humps themselves are probably overhead in unpacking the compressed kmer data. I'm a little surprised at how big that is...but is seems to be released when done, so no damage.

Do you know what the first 16 minutes was doing? Just downloading data? 36 cores seems overkill here. I'd expect using 16 cores, or maybe even just 8, would be better. It looks like 20 minutes of loading data for a one minute compute. For full impact, I'd have to support computing with 8 threads, but loading all 64 pieces in parallel. Easy to do, just need another command line option (that I might not expose to canu though).

[SHuang-Broad]

@brianwalenz Sorry it took me so long to get back to you! (multiple projects...)

It's relieving to know this is expected!

---

Do you know what the first 16 minutes was doing? Just downloading data?

No, all data has been localized and put in the right place before canu is called.

Below is the relevant part of the log file. (Please bear in mind that this is my personal fork of canu 1.9, with only the Perl part of workflow control changed). You can see that the first minute is spent on configuring the child long read splitting job. Then not much log is available.

Wed Jan 22 16:13:12 UTC 2020
Limiting hap memory to: 29 G
-- Canu branch sh_fix_k_31 +25 changes (r9633 7e2fd9ae685e1c67848a973ef3ea7858d2ae1a0b)
--
-- CITATIONS
--
-- Koren S, Walenz BP, Berlin K, Miller JR, Phillippy AM.
-- Canu: scalable and accurate long-read assembly via adaptive k-mer weighting and repeat separation.
-- Genome Res. 2017 May;27(5):722-736.
-- http://doi.org/10.1101/gr.215087.116
-- 
-- Koren S, Rhie A, Walenz BP, Dilthey AT, Bickhart DM, Kingan SB, Hiendleder S, Williams JL, Smith TPL, Phillippy AM.
-- De novo assembly of haplotype-resolved genomes with trio binning.
-- Nat Biotechnol. 2018
-- https//doi.org/10.1038/nbt.4277
-- 
-- Read and contig alignments during correction, consensus and GFA building use:
--   Šošic M, Šikic M.
--   Edlib: a C/C ++ library for fast, exact sequence alignment using edit distance.
--   Bioinformatics. 2017 May 1;33(9):1394-1395.
--   http://doi.org/10.1093/bioinformatics/btw753
-- 
-- Overlaps are generated using:
--   Berlin K, et al.
--   Assembling large genomes with single-molecule sequencing and locality-sensitive hashing.
--   Nat Biotechnol. 2015 Jun;33(6):623-30.
--   http://doi.org/10.1038/nbt.3238
-- 
--   Myers EW, et al.
--   A Whole-Genome Assembly of Drosophila.
--   Science. 2000 Mar 24;287(5461):2196-204.
--   http://doi.org/10.1126/science.287.5461.2196
-- 
-- Corrected read consensus sequences are generated using an algorithm derived from FALCON-sense:
--   Chin CS, et al.
--   Phased diploid genome assembly with single-molecule real-time sequencing.
--   Nat Methods. 2016 Dec;13(12):1050-1054.
--   http://doi.org/10.1038/nmeth.4035
-- 
-- Contig consensus sequences are generated using an algorithm derived from pbdagcon:
--   Chin CS, et al.
--   Nonhybrid, finished microbial genome assemblies from long-read SMRT sequencing data.
--   Nat Methods. 2013 Jun;10(6):563-9
--   http://doi.org/10.1038/nmeth.2474
-- 
-- CONFIGURE CANU
--
-- Detected Java(TM) Runtime Environment '1.8.0_232' (from '/usr/local/openjdk-8/bin/java') with -d64 support.
--
-- WARNING:
-- WARNING:  Failed to run gnuplot using command 'gnuplot'.
-- WARNING:  Plots will be disabled.
-- WARNING:
--
-- Detected 36 CPUs and 32 gigabytes of memory.
-- No grid engine detected, grid disabled.
--
--                            (tag)Concurrency
--                     (tag)Threads          |
--            (tag)Memory         |          |
--        (tag)         |         |          |     total usage     algorithm
--        -------  ------  --------   --------  -----------------  -----------------------------
-- Local: hap       29 GB   36 CPUs x   1 job     29 GB   36 CPUs  (read-to-haplotype assignment)
--
-- Found PacBio uncorrected reads in the input files.
--
-- Generating assembly 'giab' in '/cromwell_root/workdir'
--
-- Parameters:
--
--  genomeSize        3100000000
--
--  Overlap Generation Limits:
--    corOvlErrorRate 0.2400 ( 24.00%)
--    obtOvlErrorRate 0.0450 (  4.50%)
--    utgOvlErrorRate 0.0450 (  4.50%)
--
--  Overlap Processing Limits:
--    corErrorRate    0.3000 ( 30.00%)
--    obtErrorRate    0.0450 (  4.50%)
--    utgErrorRate    0.0450 (  4.50%)
--    cnsErrorRate    0.0750 (  7.50%)
--
-- USING k = 21
--
--
--
-- BEGIN ASSIGNING CHILD LONG READS
--
--
-- Finished stage 'haplotypeReadsConfigure', reset canuIteration.
-- New report created.
--
-- Running jobs.  First attempt out of 2.
----------------------------------------
-- Starting 'hap' concurrent execution on Wed Jan 22 16:14:30 2020 with 144.726 GB free disk space (1 processes; 1 concurrently)

    cd haplotype
    ./splitHaplotype.sh 1 > ./splitHaplotype.000001.out 2>&1

-- Finished on Wed Jan 22 20:43:42 2020 (16152 seconds) with 118.17 GB free disk space
----------------------------------------
-- Found 1 haplotyping outputs.
-- No change in report.
-- Finished stage 'haplotype-reads', reset canuIteration.
Stop requested after 'haplotype'.

The out file generated from running the shell script is here, but no time is given so I really don't know what's happening during the first 16 minutes.

Found perl:
   /usr/bin/perl
   This is perl 5, version 24, subversion 1 (v5.24.1) built for x86_64-linux-gnu-thread-multi

Found java:
   /usr/local/openjdk-8/bin/java
   Picked up _JAVA_OPTIONS: -Djava.io.tmpdir=/cromwell_root/tmp.e0308cfc

Found canu:
   /opt/canu/Linux-amd64/bin/canu
   Canu branch sh_fix_k_31 +25 changes (r9633 7e2fd9ae685e1c67848a973ef3ea7858d2ae1a0b)

Running job 1 based on command line options.
--
-- Loading haplotype data, using up to 14 GB memory for each.
--
--  Haplotype './0-kmers/haplotype-Father.meryl':
--   use kmers with frequency at least 11.

 p       prefixes             bits gigabytes (allowed: 14 GB)
-- -------------- ---------------- ---------
17         131072       5217764780     0.607
18         262144       5158499152     0.601
19         524288       5107622132     0.595
20        1048576       5073522328     0.591
21        2097152       5072976956     0.591 (smallest)
22        4194304       5139540448     0.598
23        8388608       5340321668     0.622
24       16777216       5809538344     0.676
25       33554432       6815625932     0.793
26       67108864       8895455344     1.036
27      134217728      13122768404     1.528
28      268435456      21645048760     2.520
29      536870912      38757263708     4.512
30     1073741824      73049347840     8.504 (used)
31     2147483648     141701170340    16.496
32     4294967296     279072469576    32.488
33     8589934592     553882722284    64.480
34    17179869184    1103570881936   128.473
-- -------------- ---------------- ---------

For 67654236 distinct 31-mers (with 30 bits used for indexing and 32 bits for tags):
    8.504 GB memory
    8.000 GB memory for index (1073741824 elements 64 bits wide)
    0.252 GB memory for tags  (67654236 elements 32 bits wide)
    0.252 GB memory for data  (67654236 elements 32 bits wide)

Will load 67654236 kmers.  Skipping 12511147671 (too low) and 0 (too high) kmers.
Allocating space for 67654236 suffixes of 32 bits each -> 2164935552 bits (0.252 GB) in blocks of 32.000 MB
                     67654236 values   of 32 bits each -> 2164935552 bits (0.252 GB) in blocks of 32.000 MB
Loaded 67654236 kmers.  Skipped 12511147671 (too low) and 0 (too high) kmers.
--   loaded 67654236 kmers.
--  Haplotype './0-kmers/haplotype-Mother.meryl':
--   use kmers with frequency at least 13.

 p       prefixes             bits gigabytes (allowed: 14 GB)
-- -------------- ---------------- ---------
16          65536       4434263272     0.516
17         131072       4381661820     0.510
18         262144       4333254672     0.504
19         524288       4293236132     0.500
20        1048576       4269994808     0.497 (smallest)
21        2097152       4280307916     0.498
22        4194304       4357729888     0.507
23        8388608       4569369588     0.532
24       16777216       5049444744     0.588
25       33554432       6066390812     0.706
26       67108864       8157078704     0.950
27      134217728      12395250244     1.443
28      268435456      20928389080     2.436
29      536870912      38051462508     4.430 (used)
30     1073741824      72354405120     8.423
31     2147483648     141017086100    16.417
32     4294967296     278399243816    32.410
33     8589934592     553220355004    64.403
-- -------------- ---------------- ---------

For 56795756 distinct 31-mers (with 29 bits used for indexing and 33 bits for tags):
    4.430 GB memory
    4.000 GB memory for index (536870912 elements 64 bits wide)
    0.218 GB memory for tags  (56795756 elements 33 bits wide)
    0.212 GB memory for data  (56795756 elements 32 bits wide)

Will load 56795756 kmers.  Skipping 12911257945 (too low) and 0 (too high) kmers.
Allocating space for 56795756 suffixes of 33 bits each -> 1874259948 bits (0.218 GB) in blocks of 32.000 MB
                     56795756 values   of 32 bits each -> 1817464192 bits (0.212 GB) in blocks of 32.000 MB
Loaded 56795756 kmers.  Skipped 12911257945 (too low) and 0 (too high) kmers.
--   loaded 56795756 kmers.
-- Data loaded.
--
-- Processing reads in batches of 100 reads each.
--
-- Bye.