walltime is twice cpu seconds

[jsmedmar]

First thanks for such a nice tool.

From samblaster's stderr:

samblaster: Marked   260861786 of 1716036289 (15.201%) total read ids as duplicates using 26070192k memory in 1H6M37S(3996.760S) CPU seconds and 2H28S(7228S) wall time.

Any clue why could wall time be 2X cpu time? I'm writing read by read to stdin from python, perhaps I should buffer and write big chunks at the same time? By the way, I'm 100% sure IO is not the issue

[GregoryFaust]

The wall time is not such an important statistic. When running any program through a pipe, the wall time can be much higher than the runtime of the program due to the cost of all the other programs in the entire pipe. I would guess that writing big chunks of SAM lines would have a very marginal improvement if any (it saves some IO interrupt time). In this case, the increased wall time is probably due to the runtime costs of the python code itself.

[jsmedmar]

Hi Gregory, thanks for your quick response.

Interestingly I'm not piping anything, just running samblaster:

from os.path import join
from subprocess import Popen
from subprocess import PIPE

sams = [...] # list of many sam files
process = Popen(["samblaster", "-o", "/path/to/output"], stdin=PIPE)
first = True

for i in sams:
    with open(i) as f:
        for j in f:
            if not j.startswith("@") or first:
                process.stdin.write(j)
        first = False

output, _ = process.communicate()
assert not process.returncode, output

Wondering if the bottleneck here is the speed at which python can read the files? That would be surprising

[jsmedmar]

I just tried samblaster with a 4G sam, no pipes:

>$ time samblaster -i input.sam -o output.sam

samblaster: Version 0.1.26
samblaster: Opening input.sam for read.
samblaster: Opening output.sam for write.
samblaster: Loaded 86 header sequence entries.
samblaster:
samblaster: Pair Type        Type_ID_Count   %Type/All_IDs Dup_ID_Count  %Dups/Type_ID_Count  %Dups/All_Dups  %Dups/All_IDs
samblaster: ---------------------------------------------------------------------------------------------------------------
samblaster: Both Unmapped            9297         0.140              0           0.000             0.000          0.000
samblaster: Orphan/Singleton        16671         0.250            391           2.345             0.020          0.006
samblaster: Both Mapped           6633120        99.610        1951539          29.421            99.980         29.306
samblaster: Total                 6659088       100.000        1951930          29.312           100.000         29.312
samblaster:
samblaster: Marked     1951930 of    6659088 (29.312%) total read ids as duplicates using 105136k memory in 18.860S CPU seconds and 5M45S(345S) wall time.

real	5m35.531s
user	0m18.666s
sys	0m40.231s

I still don't understand why wall time and cpu times are so different, maybe the time reading and writing the file?

Although:

>$ time cat input.sam > tmp.sam

real	0m27.277s
user	0m0.062s
sys	0m3.748s