[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
Re: Profiling of man-db database generation with zlib vs zstd
|
From: |
Maxim Cournoyer |
|
Subject: |
Re: Profiling of man-db database generation with zlib vs zstd |
|
Date: |
Sat, 26 Mar 2022 23:44:12 -0400 |
|
User-agent: |
Gnus/5.13 (Gnus v5.13) Emacs/27.2 (gnu/linux) |
Hello,
Maxim Cournoyer <maxim.cournoyer@gmail.com> writes:
> Hi Ludovic!
>
> Ludovic Courtès <ludo@gnu.org> writes:
>
>> Hi,
>>
>> Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:
>>
>>> scheme@(guix man-db)> ,profile (define a (mandb-entries
>>> "/gnu/store/jgc63dxvpd8zq0p8al71x07a02qj8i1b-man-pages-5.13/share/man"))
>>> % cumulative self
>>> time seconds seconds procedure
>>> 20.95 1.98 1.75 gdbm.scm:122:11
>>> 20.95 1.75 1.75 string-tokenize
>>> 19.37 3.61 1.62 set-procedure-property!
>>> 6.72 0.56 0.56 ice-9/eval.scm:604:6
>>> 4.35 0.36 0.36 %read-line
>>> 4.35 0.36 0.36 anon #xa8e0b0
>>> 2.77 0.23 0.23 apply-smob/1
>>> 1.58 11.51 0.13 ice-9/eval.scm:292:11
>>
>> Could it be that man-db.scm is being interpreted, hence eval.scm and
>> ‘set-procedure-property!’ here? (Running ‘make’ doesn’t compile it.)
OK, I've now compiled guix/man-db.scm with -O3, generated a profile with
~5300 manuals (guix shell --no-grafts --pure man-db perl@5.14 man-pages
libx11:doc gnutls-dane:doc my-tcl) on core-updates with my local changes
to compress man pages with zstd and profiled:
--8<---------------cut here---------------start------------->8---
scheme@(guix man-db)> ,profile (define a (mandb-entries
"/gnu/store/jp1kjkz5m116r960gvjk1sj4b0fkb0ip-profile/share/man"))
% cumulative self
time seconds seconds procedure
69.37 16.19 16.15 %read-line
14.14 3.31 3.29 string-tokenize
5.76 1.34 1.34 gdbm.scm:122:11
2.44 22.75 0.57 guix/man-db.scm:170:4
1.92 1.71 0.45 make-bytevector
1.57 0.37 0.37 anon #x209d110
0.52 0.14 0.12 open-file
0.35 16.96 0.08 ice-9/rdelim.scm:193:0:read-line
0.35 0.08 0.08 string<?
0.35 0.08 0.08 bytevector->pointer
0.26 0.06 0.06 assv-ref
0.26 0.06 0.06 readdir
0.26 0.06 0.06 equal?
0.26 0.06 0.06 get-bytevector-n!
0.17 0.67 0.04 zstd.scm:234:2:read!
0.17 0.04 0.04 string-append
0.17 0.04 0.04 close-port
0.17 0.04 0.04 bytevector-u64-native-set!
0.17 0.04 0.04 stat
0.17 0.04 0.04 guix/man-db.scm:139:19
0.09 1.83 0.02 zstd.scm:216:0:make-zstd-input-port
0.09 0.33 0.02 ice-9/ftw.scm:445:2:loop
0.09 0.12 0.02 system/foreign.scm:150:0:write-c-struct
0.09 0.04 0.02 system/foreign.scm:167:0:read-c-struct
0.09 0.02 0.02 pointer->bytevector
0.09 0.02 0.02 regexp-exec
0.09 0.02 0.02 string
0.09 0.02 0.02 sizeof
0.09 0.02 0.02 basename
0.09 0.02 0.02 string-contains
0.09 0.02 0.02 lstat
0.09 0.02 0.02 force
0.09 0.02 0.02 anon #x209d0d8
0.00 34249.92 0.00 ice-9/boot-9.scm:220:5:map1
0.00 23.28 0.00 <current input>:3:9
0.00 17.17 0.00 ice-9/ports.scm:429:0:call-with-port
0.00 7.46 0.00 zstd.scm:273:0:call-with-zstd-input-port
0.00 1.34 0.00 anon #x208c5f0
0.00 1.34 0.00 %after-gc-thunk
0.00 0.73 0.00 guix/man-db.scm:129:0:read-synopsis
0.00 0.67 0.00 %read-line
0.00 0.28 0.00 guix/man-db.scm:205:0:mandb-entries
0.00 0.16 0.00 srfi/srfi-1.scm:452:2:fold
0.00 0.16 0.00 anon #x208c57c
0.00 0.16 0.00 guix/build/utils.scm:487:0:find-files
0.00 0.14 0.00 guix/man-db.scm:155:0:man-page->entry
0.00 0.12 0.00 system/foreign.scm:182:0:make-c-struct
0.00 0.08 0.00 sort
0.00 0.04 0.00 filter
0.00 0.04 0.00 close-port
0.00 0.04 0.00 ice-9/boot-9.scm:1971:6
0.00 0.04 0.00 zstd.scm:208:4
0.00 0.04 0.00 guix/build/utils.scm:503:28
0.00 0.04 0.00 string-map
0.00 0.02 0.00 ice-9/boot-9.scm:1689:4:with-exception-handler
0.00 0.02 0.00 system/foreign.scm:187:0:parse-c-struct
0.00 0.02 0.00 guix/build/utils.scm:484:4
---
Sample count: 1146
Total time: 23.282459186 seconds (7.318256931 seconds in GC)
--8<---------------cut here---------------end--------------->8---
It still shows that parsing the files is much more expensive than
decompressing them. This is also true of zlib-compressed manuals;
here's the same experiment on master:
--8<---------------cut here---------------start------------->8---
$ guix shell --no-grafts --pure man-db perl@5.14 man-pages libx11:doc
gnutls-dane:doc tcl
[env]$ echo $GUIX_ENVIRONMENT && exit
/gnu/store/qqd7d22wf9d220prkm682yypybpr7df4-profile
$ guix shell -D guix guile-gdbm-ffi guile-zstd
[env]$ guild compile -O3 guix/man-db.scm
`/home/maxim/.cache/guile/ccache/3.0-LE-8-4.6/home/maxim/src/guix-master/guix/man-db.scm.go'
[env]$ ./pre-inst-env guix repl
scheme@(guix-user)> ,m (guix man-db)
scheme@(guix man-db)> ,profile (define a (mandb-entries
"/gnu/store/qqd7d22wf9d220prkm682yypybpr7df4-profile/share/man"))
% cumulative self
time seconds seconds procedure
49.15 2.62 2.56 string-tokenize
15.93 0.87 0.83 %read-line
10.85 0.57 0.57 anon #xd67e30
4.75 5.91 0.25 guix/man-db.scm:161:4
3.05 0.16 0.16 open-file
2.03 0.11 0.11 gdbm.scm:122:11
1.36 0.09 0.07 stat
1.36 0.07 0.07 string<?
1.36 0.07 0.07 anon #xd67df8
1.02 1.52 0.05 ice-9/rdelim.scm:193:0:read-line
1.02 0.05 0.05 regexp-exec
1.02 0.05 0.05 lstat
1.02 0.05 0.05 close-port
0.68 0.19 0.04 zlib.scm:158:0:make-gzip-input-port
0.68 0.05 0.04 string->pointer
0.68 0.04 0.04 guix/man-db.scm:134:19
0.68 0.04 0.04 bytevector->pointer
0.68 0.04 0.04 make-custom-binary-input-port
0.68 0.04 0.04 equal?
0.34 0.18 0.02 guix/man-db.scm:150:0:man-page->entry
0.34 0.02 0.02 basename
0.34 0.02 0.02 anon #xd67f10
0.34 0.02 0.02 ice-9/popen.scm:183:0:reap-pipes
0.34 0.02 0.02 zlib.scm:190:33
0.34 0.02 0.02 zlib.scm:66:0
0.00 10838.31 0.00 ice-9/boot-9.scm:220:5:map1
0.00 6.21 0.00 zlib.scm:217:0:call-with-gzip-input-port
0.00 5.22 0.00 <current input>:2:9
0.00 0.60 0.00 %read-line
0.00 0.60 0.00 zlib.scm:99:4
0.00 0.25 0.00 ice-9/ftw.scm:445:2:loop
0.00 0.25 0.00 guix/man-db.scm:196:0:mandb-entries
0.00 0.12 0.00 srfi/srfi-1.scm:452:2:fold
0.00 0.12 0.00 guix/build/utils.scm:476:0:find-files
0.00 0.12 0.00 zlib.scm:87:4
0.00 0.12 0.00 %after-gc-thunk
0.00 0.12 0.00 anon #xd5745c
0.00 0.12 0.00 anon #xd574d0
0.00 0.09 0.00 ice-9/boot-9.scm:1971:6
0.00 0.07 0.00 sort
0.00 0.07 0.00 guix/build/utils.scm:492:28
0.00 0.05 0.00 filter
0.00 0.05 0.00 ice-9/boot-9.scm:1689:4:with-exception-handler
0.00 0.04 0.00 string-map
0.00 0.04 0.00 guix/man-db.scm:200:26
0.00 0.04 0.00 close-port
0.00 0.02 0.00 guix/build/utils.scm:473:4
0.00 0.02 0.00 zlib.scm:138:4
---
Sample count: 295
Total time: 5.217801086 seconds (1.528583927 seconds in GC)
--8<---------------cut here---------------end--------------->8---
Hum, OK, so if I understand guile-zstd causes an almost 5x
slowdown... that doesn't make much sense unless the guile-zstd library
is much slower itself (zstd-decompression should be about 3.5x faster
than that of zlib).
Supposing guile-zstd was a 1:1 equivalent to guile-zlib, then we should
be able to see the above ~5 s time shrink down to around 1.5 s (best
case), which would be nice.
I'm impressed the man-db hook is that fast already though; I seem to
recall it would take like 30 s (or more?) for such a large amount of man
pages on this machine.
Thanks,
Maxim