Profiling of man-db database generation with zlib vs zstd

unofficial mirror of guix-devel@gnu.org 
 help / color / mirror / code / Atom feed

* Profiling of man-db database generation with zlib vs zstd
@ 2022-03-22 19:09 Maxim Cournoyer
  2022-03-24 21:37 ` Ludovic Courtès
  0 siblings, 1 reply; 10+ messages in thread
From: Maxim Cournoyer @ 2022-03-22 19:09 UTC (permalink / raw)
  To: guix-devel

Hello Guix,

I've spent some time looking whether the manual database generation
could be sped up by switching from compressing the manual pages with
zstd instead of zlib, which is reported to be about 3.5 times faster to
decompress.

I thought decompression would play a role because the hook is
CPU-intensive and thousands of files (depending on your profile) need to
be decompressed in order to be parsed.

But my experiment suggests otherwise: switching from zlib to zstd
currently wouldn't buy us any gain; and profiling the mandb-entries from
(guix man-db) shows something like this (current, zlib compression):

--8<---------------cut here---------------start------------->8---
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
  1.58      0.20      0.13  open-file
  1.58      0.13      0.13  ice-9/eval.scm:333:13
  1.19      0.20      0.10  ice-9/eval.scm:263:9
  1.19      0.13      0.10  ice-9/eval.scm:297:11
  0.79      0.66      0.07  ice-9/eval.scm:159:9
  0.79      0.07      0.07  ice-9/eval.scm:187:12
  0.79      0.07      0.07  ice-9/popen.scm:183:0:reap-pipes
  0.79      0.07      0.07  stat
  0.79      0.07      0.07  ice-9/eval.scm:273:7
  0.79      0.07      0.07  make-custom-binary-input-port
  0.79      0.07      0.07  anon #xa8e078
  0.79      0.07      0.07  ice-9/eval.scm:123:11
  0.40      0.76      0.03  ice-9/rdelim.scm:193:0:read-line
  0.40      0.20      0.03  ice-9/ftw.scm:445:2:loop
  0.40      0.17      0.03  zlib.scm:158:0:make-gzip-input-port
  0.40      0.03      0.03  ice-9/eval.scm:182:7
  0.40      0.03      0.03  ice-9/eval.scm:329:11
  0.40      0.03      0.03  string-trim-both
  0.40      0.03      0.03  ice-9/eval.scm:125:11
  0.40      0.03      0.03  dup->fdes
  0.40      0.03      0.03  ice-9/eval.scm:226:7
  0.40      0.03      0.03  string<?
  0.40      0.03      0.03  ice-9/eval.scm:330:13
  0.40      0.03      0.03  equal?
  0.40      0.03      0.03  ice-9/eval.scm:155:9
  0.40      0.03      0.03  ice-9/eval.scm:124:11
  0.40      0.03      0.03  regexp-exec
  0.40      0.03      0.03  ice-9/eval.scm:417:6
  0.40      0.03      0.03  zlib.scm:66:0
  0.40      0.03      0.03  ice-9/ftw.scm:218:12:string=?@guile
  0.00  10070.94      0.00  ice-9/boot-9.scm:220:5:map1
  0.00     12.57      0.00  zlib.scm:217:0:call-with-gzip-input-port
  0.00      8.37      0.00  <current input>:11:9
  0.00      3.64      0.00  ice-9/eval.scm:586:29
  0.00      2.05      0.00  %after-gc-thunk
  0.00      2.05      0.00  anon #xa7d750
  0.00      1.98      0.00  ice-9/eval.scm:212:12
  0.00      1.46      0.00  string-map
  0.00      0.36      0.00  %read-line
  0.00      0.36      0.00  zlib.scm:99:4
  0.00      0.20      0.00  ice-9/eval.scm:618:6
  0.00      0.10      0.00  guix/build/utils.scm:476:0:find-files
  0.00      0.10      0.00  ice-9/eval.scm:244:10
  0.00      0.10      0.00  anon #xa7d6dc
  0.00      0.10      0.00  ice-9/eval.scm:625:6
  0.00      0.10      0.00  srfi/srfi-1.scm:452:2:fold
  0.00      0.07      0.00  zlib.scm:87:4
  0.00      0.07      0.00  ice-9/boot-9.scm:1971:6
  0.00      0.03      0.00  sort
  0.00      0.03      0.00  ice-9/eval.scm:263:9
  0.00      0.03      0.00  guix/build/utils.scm:492:28
---
Sample count: 253
Total time: 8.368360886 seconds (5.356567327 seconds in GC)
--8<---------------cut here---------------end--------------->8---

When rebuilding the man-pages package with zstd compressed manuals and
using guile-zstd to read them, we instead get:

--8<---------------cut here---------------start------------->8---
scheme@(guix man-db)> ,profile (define a (mandb-entries "/gnu/store/dsm4wkzgzq6i00xc765vpgdzb0aq99fa-man-pages-5.13/share/man"))
%     cumulative   self             
time   seconds     seconds  procedure
 28.93      2.38      2.34  gdbm.scm:122:11
 18.60      3.82      1.51  set-procedure-property!
 12.81      1.04      1.04  string-tokenize
  7.02      0.57      0.57  ice-9/eval.scm:604:6
  4.55      0.37      0.37  make-bytevector
  4.13      0.33      0.33  %read-line
  3.31      0.27      0.27  anon #x1bb01e0
  1.65      0.17      0.13  ice-9/eval.scm:263:9
  1.65      0.13      0.13  stat
  1.24      0.90      0.10  ice-9/rdelim.scm:193:0:read-line
  1.24      0.10      0.10  ice-9/eval.scm:342:13
  1.24      0.10      0.10  ice-9/eval.scm:125:11
  1.24      0.10      0.10  regexp-exec
  0.83      0.10      0.07  ice-9/eval.scm:155:9
  0.83      0.07      0.07  ice-9/eval.scm:333:13
  0.83      0.07      0.07  pointer->bytevector
  0.83      0.07      0.07  anon #x1bb01a8
  0.83      0.07      0.07  ice-9/eval.scm:187:12
  0.83      0.07      0.07  string<?
  0.83      0.07      0.07  get-bytevector-n!
  0.41     11.92      0.03  zstd.scm:273:0:call-with-zstd-input-port
  0.41     10.72      0.03  ice-9/eval.scm:292:11
  0.41      1.91      0.03  ice-9/eval.scm:212:12
  0.41      0.03      0.03  ice-9/eval.scm:123:11
  0.41      0.03      0.03  ice-9/eval.scm:273:7
  0.41      0.03      0.03  string-suffix?
  0.41      0.03      0.03  ice-9/eval.scm:155:9
  0.41      0.03      0.03  readdir
  0.41      0.03      0.03  system/foreign.scm:188:20
  0.41      0.03      0.03  ice-9/eval.scm:182:7
  0.41      0.03      0.03  apply-smob/1
  0.41      0.03      0.03  string-contains
  0.41      0.03      0.03  ice-9/rdelim.scm:93:23:string-append@guile
  0.41      0.03      0.03  equal?
  0.41      0.03      0.03  close-port
  0.41      0.03      0.03  ice-9/eval.scm:126:12
  0.00   9965.18      0.00  ice-9/boot-9.scm:220:5:map1
  0.00      8.10      0.00  <current input>:5:9
  0.00      3.82      0.00  ice-9/eval.scm:586:29
  0.00      2.38      0.00  anon #x1b9f6c0
  0.00      2.38      0.00  %after-gc-thunk
  0.00      1.57      0.00  string-map
  0.00      0.57      0.00  ice-9/eval.scm:159:9
  0.00      0.47      0.00  %read-line
  0.00      0.47      0.00  zstd.scm:234:2:read!
  0.00      0.44      0.00  zstd.scm:216:0:make-zstd-input-port
  0.00      0.27      0.00  ice-9/ftw.scm:445:2:loop
  0.00      0.17      0.00  srfi/srfi-1.scm:452:2:fold
  0.00      0.13      0.00  ice-9/boot-9.scm:1971:6
  0.00      0.13      0.00  ice-9/eval.scm:196:12
  0.00      0.13      0.00  ice-9/eval.scm:618:6
  0.00      0.13      0.00  guix/build/utils.scm:487:0:find-files
  0.00      0.13      0.00  anon #x1b9f64c
  0.00      0.13      0.00  ice-9/eval.scm:297:11
  0.00      0.10      0.00  ice-9/eval.scm:244:10
  0.00      0.10      0.00  system/foreign.scm:187:0:parse-c-struct
  0.00      0.10      0.00  guix/build/utils.scm:503:28
  0.00      0.07      0.00  ice-9/eval.scm:278:9
  0.00      0.07      0.00  zstd.scm:208:4
  0.00      0.07      0.00  filter
  0.00      0.07      0.00  ice-9/eval.scm:625:6
  0.00      0.07      0.00  sort
  0.00      0.07      0.00  ice-9/eval.scm:259:9
  0.00      0.03      0.00  open-file
  0.00      0.03      0.00  close-port
  0.00      0.03      0.00  ice-9/eval.scm:191:12
  0.00      0.03      0.00  bytevector->pointer
---
Sample count: 242
Total time: 8.104984533 seconds (5.253193735 seconds in GC)
--8<---------------cut here---------------end--------------->8---

So, it seems the parsing of the manual files itself in Guile (to
retrieve their name, synopsis, etc.) is what is using most of the time
(CPU-bound).

Perhaps this can be optimized?

Maxim


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-22 19:09 Profiling of man-db database generation with zlib vs zstd Maxim Cournoyer
@ 2022-03-24 21:37 ` Ludovic Courtès
  2022-03-26  3:22   ` Maxim Cournoyer
  2022-03-28  3:49   ` Maxim Cournoyer
  0 siblings, 2 replies; 10+ messages in thread
From: Ludovic Courtès @ 2022-03-24 21:37 UTC (permalink / raw)
  To: Maxim Cournoyer; +Cc: guix-devel

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.)

With a compiled man-db.scm, I get:

--8<---------------cut here---------------start------------->8---
scheme@(guile-user)> ,profile (define a (mandb-entries "/gnu/store/jgc63dxvpd8zq0p8al71x07a02qj8i1b-man-pages-5.13/share/man"))
%     cumulative   self             
time   seconds     seconds  procedure
 62.26      0.65      0.65  string-tokenize
 11.32      0.12      0.12  anon #xc76118
  3.77      0.16      0.04  ice-9/suspendable-ports.scm:651:0:read-delimited
  3.77      0.04      0.04  open-file
  1.89      1.35      0.02  /home/ludo/src/guix/guix/man-db.scm:161:4
  1.89      0.04      0.02  stat
  1.89      0.02      0.02  ice-9/popen.scm:183:0:reap-pipes
  1.89      0.02      0.02  string->pointer
  1.89      0.02      0.02  close-port
  1.89      0.02      0.02  anon #xc760e0
  1.89      0.02      0.02  fileno
  1.89      0.02      0.02  string<?
  1.89      0.02      0.02  ice-9/suspendable-ports.scm:203:4
  1.89      0.02      0.02  lstat
  0.00   1220.43      0.00  ice-9/boot-9.scm:220:5:map1
  0.00      1.45      0.00  zlib.scm:217:0:call-with-gzip-input-port
  0.00      1.05      0.00  <current input>:2756:9
  0.00      0.12      0.00  ice-9/suspendable-ports.scm:70:0:read-bytes
  0.00      0.12      0.00  port-read
  0.00      0.12      0.00  zlib.scm:99:4
  0.00      0.12      0.00  ice-9/suspendable-ports.scm:158:0:fill-input
  0.00      0.08      0.00  zlib.scm:158:0:make-gzip-input-port
  0.00      0.06      0.00  /home/ludo/src/guix/guix/man-db.scm:196:0:mandb-entries
  0.00      0.04      0.00  zlib.scm:87:4
  0.00      0.04      0.00  /home/ludo/src/guix/guix/man-db.scm:150:0:man-page->entry
  0.00      0.04      0.00  /home/ludo/src/guix/guix/man-db.scm:191:0:man-files
  0.00      0.04      0.00  ice-9/ftw.scm:445:2:loop
  0.00      0.04      0.00  ice-9/boot-9.scm:1971:6
  0.00      0.02      0.00  %after-gc-thunk
  0.00      0.02      0.00  anon #xbbc5b0
  0.00      0.02      0.00  ice-9/boot-9.scm:1689:4:with-exception-handler
  0.00      0.02      0.00  guix/build/utils.scm:476:0:find-files
  0.00      0.02      0.00  sort
  0.00      0.02      0.00  filter
  0.00      0.02      0.00  /home/ludo/src/guix/guix/man-db.scm:200:26
  0.00      0.02      0.00  srfi/srfi-1.scm:452:2:fold
  0.00      0.02      0.00  anon #xbbc53c
---
Sample count: 53
Total time: 1.049704017 seconds (0.358461379 seconds in GC)
--8<---------------cut here---------------end--------------->8---

More samples would give a more exploitable profile though.

HTH!

Ludo’.


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-24 21:37 ` Ludovic Courtès
@ 2022-03-26  3:22   ` Maxim Cournoyer
  2022-03-27  3:44     ` Maxim Cournoyer
  2022-03-28  3:49   ` Maxim Cournoyer
  1 sibling, 1 reply; 10+ messages in thread
From: Maxim Cournoyer @ 2022-03-26  3:22 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: guix-devel

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.)
>
> With a compiled man-db.scm, I get:
>
> scheme@(guile-user)> ,profile (define a (mandb-entries "/gnu/store/jgc63dxvpd8zq0p8al71x07a02qj8i1b-man-pages-5.13/share/man"))
> %     cumulative   self             
> time   seconds     seconds  procedure
>  62.26      0.65      0.65  string-tokenize
>  11.32      0.12      0.12  anon #xc76118
>   3.77      0.16      0.04  ice-9/suspendable-ports.scm:651:0:read-delimited
>   3.77      0.04      0.04  open-file
>   1.89      1.35      0.02  /home/ludo/src/guix/guix/man-db.scm:161:4
>   1.89      0.04      0.02  stat
>   1.89      0.02      0.02  ice-9/popen.scm:183:0:reap-pipes
>   1.89      0.02      0.02  string->pointer
>   1.89      0.02      0.02  close-port
>   1.89      0.02      0.02  anon #xc760e0
>   1.89      0.02      0.02  fileno
>   1.89      0.02      0.02  string<?
>   1.89      0.02      0.02  ice-9/suspendable-ports.scm:203:4
>   1.89      0.02      0.02  lstat
>   0.00   1220.43      0.00  ice-9/boot-9.scm:220:5:map1
>   0.00      1.45      0.00  zlib.scm:217:0:call-with-gzip-input-port
>   0.00      1.05      0.00  <current input>:2756:9
>   0.00      0.12      0.00  ice-9/suspendable-ports.scm:70:0:read-bytes
>   0.00      0.12      0.00  port-read
>   0.00      0.12      0.00  zlib.scm:99:4
>   0.00      0.12      0.00  ice-9/suspendable-ports.scm:158:0:fill-input
>   0.00      0.08      0.00  zlib.scm:158:0:make-gzip-input-port
>   0.00      0.06      0.00  /home/ludo/src/guix/guix/man-db.scm:196:0:mandb-entries
>   0.00      0.04      0.00  zlib.scm:87:4
>   0.00      0.04      0.00  /home/ludo/src/guix/guix/man-db.scm:150:0:man-page->entry
>   0.00      0.04      0.00  /home/ludo/src/guix/guix/man-db.scm:191:0:man-files
>   0.00      0.04      0.00  ice-9/ftw.scm:445:2:loop
>   0.00      0.04      0.00  ice-9/boot-9.scm:1971:6
>   0.00      0.02      0.00  %after-gc-thunk
>   0.00      0.02      0.00  anon #xbbc5b0
>   0.00      0.02      0.00  ice-9/boot-9.scm:1689:4:with-exception-handler
>   0.00      0.02      0.00  guix/build/utils.scm:476:0:find-files
>   0.00      0.02      0.00  sort
>   0.00      0.02      0.00  filter
>   0.00      0.02      0.00  /home/ludo/src/guix/guix/man-db.scm:200:26
>   0.00      0.02      0.00  srfi/srfi-1.scm:452:2:fold
>   0.00      0.02      0.00  anon #xbbc53c
> ---
> Sample count: 53
> Total time: 1.049704017 seconds (0.358461379 seconds in GC)
>
> More samples would give a more exploitable profile though.

Thanks!  I tried generating a profile containing these high manpages
count: man-pages (~2400), perl (~800), libx11 (~800), gnutls (~1200),
tcl (~850), calibre (~700)

Which should give a collection of close to 7000 manpages, or roughly 3
times larger than 'man-pages' alone.

Unfortunately, it seems something else wants my attention:

--8<---------------cut here---------------start------------->8---
$ ./pre-inst-env guix shell --no-grafts --pure man-db perl@5.14 man-pages libx11:doc gnutls-dane:doc my-tcl calibre
[...]
substitute: updating substitutes from 'http://127.0.0.1:8181'...  36.4%Backtrace:
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 17 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In unknown file:
substitute:           16 (apply-smob/0 #<thunk 7f343a1962e0>)
substitute: In ice-9/boot-9.scm:
substitute:     724:2 15 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
substitute: In ice-9/eval.scm:
substitute:     619:8 14 (_ #(#(#<directory (guile-user) 7f343a19bc80>)))
substitute: In guix/ui.scm:
substitute:    2247:7 13 (run-guix . _)
substitute:   2210:10 12 (run-guix-command _ . _)
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 11 (with-exception-handler _ _ #:unwind? _ # _)
substitute:   1752:10 10 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In guix/scripts/substitute.scm:
substitute:    757:18  9 (_)
substitute:    348:26  8 (process-query #<output: file 4> _ #:cache-urls _ #:acl _)
substitute: In guix/substitutes.scm:
substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure 7f3437718ee0 …> …)
substitute:    322:31  6 (lookup-narinfos _ _ #:open-connection _ # _)
substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ # _)
substitute: In ice-9/boot-9.scm:
substitute:   1685:16  4 (raise-exception _ #:continuable? _)
substitute:   1685:16  3 (raise-exception _ #:continuable? _)
substitute:   1780:13  2 (_ #<&compound-exception components: (#<&assertion-fail…>)
substitute:   1685:16  1 (raise-exception _ #:continuable? _)
substitute:   1685:16  0 (raise-exception _ #:continuable? _)
substitute: 
substitute: ice-9/boot-9.scm:1685:16: In procedure raise-exception:
substitute: Wrong type (expecting exact integer): #f
guix shell: error: `/gnu/store/pw3g3c2vpy6xyibp077875gb8xascgwa-guix-1.3.0-24.2fb4304/bin/guix substitute' died unexpectedly

$ ./pre-inst-env guix shell --no-grafts --pure man-db perl@5.14 man-pages libx11:doc gnutls-dane:doc my-tcl calibre
[...]
substitute: updating substitutes from 'http://127.0.0.1:8181'...  25.2%Backtrace:
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 17 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In unknown file:
substitute:           16 (apply-smob/0 #<thunk 7f5a78cef2e0>)
substitute: In ice-9/boot-9.scm:
substitute:     724:2 15 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
substitute: In ice-9/eval.scm:
substitute:     619:8 14 (_ #(#(#<directory (guile-user) 7f5a78cf4c80>)))
substitute: In guix/ui.scm:
substitute:    2247:7 13 (run-guix . _)
substitute:   2210:10 12 (run-guix-command _ . _)
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 11 (with-exception-handler _ _ #:unwind? _ # _)
substitute:   1752:10 10 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In guix/scripts/substitute.scm:
substitute:    757:18  9 (_)
substitute:    348:26  8 (process-query #<output: file 4> _ #:cache-urls _ #:acl _)
substitute: In guix/substitutes.scm:
substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure 7f5a76252e00 …> …)
substitute:    322:31  6 (lookup-narinfos _ _ #:open-connection _ # _)
substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ # _)
substitute: In ice-9/boot-9.scm:
substitute:   1685:16  4 (raise-exception _ #:continuable? _)
substitute:   1685:16  3 (raise-exception _ #:continuable? _)
substitute:   1780:13  2 (_ #<&compound-exception components: (#<&assertion-fail…>)
substitute:   1685:16  1 (raise-exception _ #:continuable? _)
substitute:   1685:16  0 (raise-exception _ #:continuable? _)
substitute: 
substitute: ice-9/boot-9.scm:1685:16: In procedure raise-exception:
substitute: Wrong type (expecting exact integer): #f
guix shell: error:
`/gnu/store/pw3g3c2vpy6xyibp077875gb8xascgwa-guix-1.3.0-24.2fb4304/bin/guix
substitute' died unexpectedly

$ ./pre-inst-env guix shell --no-grafts --pure man-db perl@5.14 man-pages libx11:doc gnutls-dane:doc my-tcl calibre
[...]
substitute: updating substitutes from 'http://127.0.0.1:8181'...  32.0%Backtrace:
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 17 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In unknown file:
substitute:           16 (apply-smob/0 #<thunk 7ff772ca92e0>)
substitute: In ice-9/boot-9.scm:
substitute:     724:2 15 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
substitute: In ice-9/eval.scm:
substitute:     619:8 14 (_ #(#(#<directory (guile-user) 7ff772caec80>)))
substitute: In guix/ui.scm:
substitute:    2247:7 13 (run-guix . _)
substitute:   2210:10 12 (run-guix-command _ . _)
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 11 (with-exception-handler _ _ #:unwind? _ # _)
substitute:   1752:10 10 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In guix/scripts/substitute.scm:
substitute:    757:18  9 (_)
substitute:    348:26  8 (process-query #<output: file 4> _ #:cache-urls _ #:acl _)
substitute: In guix/substitutes.scm:
substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure 7ff770204b40 …> …)
substitute:    322:31  6 (lookup-narinfos _ _ #:open-connection _ # _)
substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ # _)
substitute: In ice-9/boot-9.scm:
substitute:   1685:16  4 (raise-exception _ #:continuable? _)
substitute:   1685:16  3 (raise-exception _ #:continuable? _)
substitute:   1780:13  2 (_ #<&compound-exception components: (#<&assertion-fail…>)
substitute:   1685:16  1 (raise-exception _ #:continuable? _)
substitute:   1685:16  0 (raise-exception _ #:continuable? _)
substitute: 
substitute: ice-9/boot-9.scm:1685:16: In procedure raise-exception:
substitute: Wrong type (expecting exact integer): #f
guix shell: error: `/gnu/store/pw3g3c2vpy6xyibp077875gb8xascgwa-guix-1.3.0-24.2fb4304/bin/guix substitute' died unexpectedly
$ ./pre-inst-env guix shell --no-grafts --pure man-db perl@5.14 man-pages libx11:doc gnutls-dane:doc my-tcl calibre
[...]
substitute: updating substitutes from 'http://127.0.0.1:8181'... 100.0%
substitute: updating substitutes from 'https://ci.guix.gnu.org'... 100.0%
guix shell: error: got unexpected path `/gnu/store/67awg434br6215jxvf3h2r6imawsbky0-cairomm-1.14.2.tar.xz' from substituter
./pre-inst-env guix shell --no-grafts --pure man-db perl@5.14 man-pages libx11:doc gnutls-dane:doc my-tcl calibre
[...]
substitute: updating substitutes from 'http://127.0.0.1:8181'...  18.5%Backtrace:
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 17 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In unknown file:
substitute:           16 (apply-smob/0 #<thunk 7fd517c2a2e0>)
substitute: In ice-9/boot-9.scm:
substitute:     724:2 15 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
substitute: In ice-9/eval.scm:
substitute:     619:8 14 (_ #(#(#<directory (guile-user) 7fd517c2fc80>)))
substitute: In guix/ui.scm:
substitute:    2247:7 13 (run-guix . _)
substitute:   2210:10 12 (run-guix-command _ . _)
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 11 (with-exception-handler _ _ #:unwind? _ # _)
substitute:   1752:10 10 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In guix/scripts/substitute.scm:
substitute:    757:18  9 (_)
substitute:    348:26  8 (process-query #<output: file 4> _ #:cache-urls _ #:acl _)
substitute: In guix/substitutes.scm:
substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure 7fd5151770e0 …> …)
substitute:    322:31  6 (lookup-narinfos _ _ #:open-connection _ # _)
substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ # _)
substitute: In ice-9/boot-9.scm:
substitute:   1685:16  4 (raise-exception _ #:continuable? _)
substitute:   1685:16  3 (raise-exception _ #:continuable? _)
substitute:   1780:13  2 (_ #<&compound-exception components: (#<&error> #<&orig…>)
substitute:   1685:16  1 (raise-exception _ #:continuable? _)
substitute:   1685:16  0 (raise-exception _ #:continuable? _)
substitute: 
substitute: ice-9/boot-9.scm:1685:16: In procedure raise-exception:
substitute: unmatched line "\r"
guix shell: error: `/gnu/store/pw3g3c2vpy6xyibp077875gb8xascgwa-guix-1.3.0-24.2fb4304/bin/guix substitute' died unexpectedly

$ ./pre-inst-env guix shell --no-grafts --pure man-db perl@5.14 man-pages libx11:doc gnutls-dane:doc my-tcl calibre
[...]
substitute: updating substitutes from 'http://127.0.0.1:8181'...  22.3%Backtrace:
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 17 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In unknown file:
substitute:           16 (apply-smob/0 #<thunk 7fbb72b382e0>)
substitute: In ice-9/boot-9.scm:
substitute:     724:2 15 (call-with-prompt _ _ #<procedure default-prompt-handle…>)
substitute: In ice-9/eval.scm:
substitute:     619:8 14 (_ #(#(#<directory (guile-user) 7fbb72b3dc80>)))
substitute: In guix/ui.scm:
substitute:    2247:7 13 (run-guix . _)
substitute:   2210:10 12 (run-guix-command _ . _)
substitute: In ice-9/boot-9.scm:
substitute:   1752:10 11 (with-exception-handler _ _ #:unwind? _ # _)
substitute:   1752:10 10 (with-exception-handler _ _ #:unwind? _ # _)
substitute: In guix/scripts/substitute.scm:
substitute:    757:18  9 (_)
substitute:    348:26  8 (process-query #<output: file 4> _ #:cache-urls _ #:acl _)
substitute: In guix/substitutes.scm:
substitute:    365:27  7 (lookup-narinfos/diverse _ _ #<procedure 7fbb7007c160 …> …)
substitute:    322:31  6 (lookup-narinfos _ _ #:open-connection _ # _)
substitute:    245:26  5 (fetch-narinfos _ _ #:open-connection _ # _)
substitute: In ice-9/boot-9.scm:
substitute:   1685:16  4 (raise-exception _ #:continuable? _)
substitute:   1685:16  3 (raise-exception _ #:continuable? _)
substitute:   1780:13  2 (_ #<&compound-exception components: (#<&assertion-fail…>)
substitute:   1685:16  1 (raise-exception _ #:continuable? _)
substitute:   1685:16  0 (raise-exception _ #:continuable? _)
substitute: 
substitute: ice-9/boot-9.scm:1685:16: In procedure raise-exception:
substitute: Wrong type (expecting exact integer): #f
guix shell: error: `/gnu/store/pw3g3c2vpy6xyibp077875gb8xascgwa-guix-1.3.0-24.2fb4304/bin/guix substitute' died unexpectedly
--8<---------------cut here---------------end--------------->8---

I forgot where I was at the last time I tried to debug this :-).

Thanks, I'll try to follow-up with the actual results if I can sort the
above.

Maxim


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-26  3:22   ` Maxim Cournoyer
@ 2022-03-27  3:44     ` Maxim Cournoyer
  2022-03-29 10:22       ` Ludovic Courtès
  0 siblings, 1 reply; 10+ messages in thread
From: Maxim Cournoyer @ 2022-03-27  3:44 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: guix-devel

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


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-27  3:44     ` Maxim Cournoyer
@ 2022-03-29 10:22       ` Ludovic Courtès
  0 siblings, 0 replies; 10+ messages in thread
From: Ludovic Courtès @ 2022-03-29 10:22 UTC (permalink / raw)
  To: Maxim Cournoyer; +Cc: guix-devel

Howdy,

Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:

> 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:
>
> 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

[...]

> Total time: 23.282459186 seconds (7.318256931 seconds in GC)
>
>
> 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:
>
> $ 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

[...]

> Total time: 5.217801086 seconds (1.528583927 seconds in GC)
>
> 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).

Zstd decompression is indeed faster than zlib decompression.  It could
be that there are other factors interfering though.

For example, since we decompress only the first few bytes of each file,
it could be that allocation/initialization of the zlib/zstd
decompression ports outweighs the actual decompression cost.  It might
be possible to visualize that with a C-level profile, using ‘perf’.

> 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.

Are you doing this on a hot cache?  I/O would normally dominate that
whole process when running ‘guix install foo’, because in that case
you’d be reading all these man pages for the first time (they’re not in
cache).

HTH,
Ludo’.


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-24 21:37 ` Ludovic Courtès
  2022-03-26  3:22   ` Maxim Cournoyer
@ 2022-03-28  3:49   ` Maxim Cournoyer
  2022-03-29 10:30     ` Ludovic Courtès
  2022-03-31 17:13     ` Ludovic Courtès
  1 sibling, 2 replies; 10+ messages in thread
From: Maxim Cournoyer @ 2022-03-28  3:49 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: guix-devel

Hi again,

Here I decided to look at the raw performance of guile-zstd vs
guile-zlib when decompressing the ungoogled-chromium source into a 4 GiB
something tarball.

You'll need to generate the tar.zst and tar.gz yourself, but the script
that was used is:

--8<---------------cut here---------------start------------->8---
;; decompress-zstd.scm
(use-modules (ice-9 binary-ports)
             (ice-9 match)
             (statprof)
             (zstd))

(define MiB (expt 2 20))
(define input-file "/tmp/chromium-98.0.4758.102.tar.zst")
(define output-file "/dev/null")

(define (decompression-test)
  (call-with-input-file input-file
    (lambda (port)
      (call-with-zstd-input-port port
        (lambda (input)
          (call-with-output-file output-file
            (lambda (output)
              (let loop ((bv (get-bytevector-n input (* 4 MiB))))
                (match bv
                  ((? eof-object?)
                   #t)
                  (bv
                   (put-bytevector output bv)
                   (loop (get-bytevector-n input (* 4 MiB)))))))))))))

(statprof (lambda ()
            (decompression-test)))
--8<---------------cut here---------------end--------------->8---

Compiled and run:
--8<---------------cut here---------------start------------->8---
$ alias time+
alias time+='command time -f"cpu: %P, mem: %M KiB, wall: %E, sys: %S, usr: %U"'
$ guild compile -O3 /tmp/decompress-zstd.scm
$ time+ guile /tmp/decompress-zstd.scm
%     cumulative   self
time   seconds     seconds  procedure
 48.69     13.93     13.93  anon #x1689100
 45.38     12.98     12.98  %after-gc-thunk
  3.47      0.99      0.99  bytevector->pointer
  0.46     28.59      0.13  zstd.scm:234:2:read!
  0.39      0.11      0.11  get-bytevector-n!
  0.23      0.22      0.07  system/foreign.scm:150:0:write-c-struct
  0.23      0.07      0.07  bytevector-u64-native-set!
  0.15      0.07      0.04  system/foreign.scm:167:0:read-c-struct
  0.15      0.04      0.04  anon #x1688ed0
  0.15      0.04      0.04  assv-ref
  0.15      0.04      0.04  system/foreign.scm:91:9
  0.08      0.26      0.02  system/foreign.scm:182:0:make-c-struct
  0.08      0.02      0.02  put-bytevector
  0.08      0.02      0.02  list?
  0.08      0.02      0.02  sizeof
  0.08      0.02      0.02  pointer->bytevector
  0.08      0.02      0.02  make-bytevector
  0.08      0.02      0.02  bytevector-u64-native-ref
  0.00     28.61      0.00  zstd.scm:273:0:call-with-zstd-input-port
  0.00     28.61      0.00  ice-9/ports.scm:438:0:call-with-input-file
  0.00     28.61      0.00  /tmp/decompress-zstd.scm:16:12
  0.00     28.61      0.00  ice-9/ports.scm:456:0:call-with-output-file
  0.00     28.59      0.00  get-bytevector-n
  0.00     12.98      0.00  anon #x167aed0
  0.00      0.07      0.00  system/foreign.scm:187:0:parse-c-struct
  0.00      0.04      0.00  zstd.scm:57:4
  0.00      0.04      0.00  srfi/srfi-1.scm:452:2:fold
  0.00      0.02      0.00  system/foreign.scm:188:20
---
Sample count: 1298
Total time: 28.614481162 seconds (15.671167152 seconds in GC)
cpu: 153%, mem: 39156 KiB, wall: 0:18.92, sys: 0.50, usr: 28.45
--8<---------------cut here---------------end--------------->8---

And for guile-zlib, after adjusting the script to:
--8<---------------cut here---------------end--------------->8---
(use-modules (ice-9 binary-ports)
             (ice-9 match)
             (statprof)
             (zlib))

(define MiB (expt 2 20))
(define input-file "/tmp/chromium-98.0.4758.102.tar.gz")
(define output-file "/dev/null")

(define (decompression-test)
  (call-with-input-file input-file
    (lambda (port)
      (call-with-gzip-input-port port
        (lambda (input)
          (call-with-output-file output-file
            (lambda (output)
              (let loop ((bv (get-bytevector-n input (* 4 MiB))))
                (match bv
                  ((? eof-object?)
                   #t)
                  (bv
                   (put-bytevector output bv)
                   (loop (get-bytevector-n input (* 4 MiB)))))))))))))

(statprof (lambda ()
            (decompression-test)))
--8<---------------cut here---------------end--------------->8---

I got:
--8<---------------cut here---------------start------------->8---
$ time+ guile /tmp/decompress-gzip.scm
%     cumulative   self
time   seconds     seconds  procedure
 71.18     21.21     21.21  anon #x218af40
 20.78      6.19      6.19  %after-gc-thunk
  5.33      1.59      1.59  bytevector->pointer
  2.39     23.51      0.71  zlib.scm:99:4
  0.32      6.29      0.09  zlib.scm:182:2:read!
  0.00     29.80      0.00  /tmp/decompress-gzip.scm:16:12
  0.00     29.80      0.00  get-bytevector-n
  0.00     29.80      0.00  ice-9/ports.scm:456:0:call-with-output-file
  0.00     29.80      0.00  zlib.scm:217:0:call-with-gzip-input-port
  0.00     29.80      0.00  ice-9/ports.scm:438:0:call-with-input-file
  0.00      6.19      0.00  anon #x217ced0
---
Sample count: 1256
Total time: 29.800587574 seconds (8.715080702 seconds in GC)
cpu: 124%, mem: 60772 KiB, wall: 0:24.12, sys: 0.56, usr: 29.54
--8<---------------cut here---------------end--------------->8---

This confirms that guile-zstd is not noticeably faster than guile-zlib,
which is unexpected.

Compare to the command line tools:

$ time+ zstd -cdk /tmp/chromium-98.0.4758.102.tar.zst > /dev/null
cpu: 99%, mem: 10548 KiB, wall: 0:09.37, sys: 0.30, usr: 9.05

$ time+ gunzip -ck /tmp/chromium-98.0.4758.102.tar.gz > /dev/null
cpu: 99%, mem: 2908 KiB, wall: 0:22.29, sys: 0.31, usr: 21.98

where zstd is about 2.3x faster.

It's unfortunate that the bulk of the time is spent in "anon" (anonymous
proc?), which doesn't say much.

Perhaps I should open an issue with the guile-zstd project.

Thanks,

Maxim


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-28  3:49   ` Maxim Cournoyer
@ 2022-03-29 10:30     ` Ludovic Courtès
  2022-03-30 14:49       ` Maxim Cournoyer
  2022-03-30 16:16       ` Jonathan McHugh
  2022-03-31 17:13     ` Ludovic Courtès
  1 sibling, 2 replies; 10+ messages in thread
From: Ludovic Courtès @ 2022-03-29 10:30 UTC (permalink / raw)
  To: Maxim Cournoyer; +Cc: guix-devel

Hi!

Maxim Cournoyer <maxim.cournoyer@gmail.com> skribis:

> You'll need to generate the tar.zst and tar.gz yourself, but the script
> that was used is:
>
> ;; decompress-zstd.scm
> (use-modules (ice-9 binary-ports)
>              (ice-9 match)
>              (statprof)
>              (zstd))
>
> (define MiB (expt 2 20))
> (define input-file "/tmp/chromium-98.0.4758.102.tar.zst")
> (define output-file "/dev/null")
>
> (define (decompression-test)
>   (call-with-input-file input-file
>     (lambda (port)
>       (call-with-zstd-input-port port
>         (lambda (input)
>           (call-with-output-file output-file
>             (lambda (output)
>               (let loop ((bv (get-bytevector-n input (* 4 MiB))))
>                 (match bv
>                   ((? eof-object?)
>                    #t)
>                   (bv
>                    (put-bytevector output bv)
>                    (loop (get-bytevector-n input (* 4 MiB)))))))))))))

To isolate the problem, you could allocate the 4 MiB buffer outside of
the loop and use ‘get-bytevector-n!’, and also remove code that writes
to ‘output’.

> This confirms that guile-zstd is not noticeably faster than guile-zlib,
> which is unexpected.

Uh, surprising.

Note that ‘statprof’ incurs overhead, so in general if you want timings,
get them without ‘statprof’.

> Compare to the command line tools:
>
> $ time+ zstd -cdk /tmp/chromium-98.0.4758.102.tar.zst > /dev/null
> cpu: 99%, mem: 10548 KiB, wall: 0:09.37, sys: 0.30, usr: 9.05
>
> $ time+ gunzip -ck /tmp/chromium-98.0.4758.102.tar.gz > /dev/null
> cpu: 99%, mem: 2908 KiB, wall: 0:22.29, sys: 0.31, usr: 21.98
>
> where zstd is about 2.3x faster.
>
> It's unfortunate that the bulk of the time is spent in "anon" (anonymous
> proc?), which doesn't say much.

It’s likely one of the lambdas.

> Perhaps I should open an issue with the guile-zstd project.

Yes, or we can continue here.  :-)

From there I think we should first fully isolate the thing we’re
measuring, as discussed above, to gain confidence.

It the code using guile-zstd is slower than the CLI, then it could be
that guile-zstd doesn’t initialize the library properly, or that it gets
buffering wrong or something.

I’ll see if I can give it a try too.

Thanks for investigating!

Ludo’.


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-29 10:30     ` Ludovic Courtès
@ 2022-03-30 14:49       ` Maxim Cournoyer
  2022-03-30 16:16       ` Jonathan McHugh
  1 sibling, 0 replies; 10+ messages in thread
From: Maxim Cournoyer @ 2022-03-30 14:49 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: guix-devel

Hi Ludovic,

Ludovic Courtès <ludo@gnu.org> writes:

[...]

> To isolate the problem, you could allocate the 4 MiB buffer outside of
> the loop and use ‘get-bytevector-n!’, and also remove code that writes
> to ‘output’.

I've adjusted the benchmark like so:

--8<---------------cut here---------------start------------->8---
(use-modules (ice-9 binary-ports)
             (ice-9 match)
             (rnrs bytevectors)
             (zstd))

(define MiB (expt 2 20))
(define block-size (* 4 MiB))
(define bv (make-bytevector block-size))
(define input-file "/tmp/chromium-98.0.4758.102.tar.zst")

(define (run)
  (call-with-input-file input-file
    (lambda (port)
      (call-with-zstd-input-port port
        (lambda (input)
          (while (not (eof-object?
                       (get-bytevector-n! input bv 0 block-size)))))))))

(run)
--8<---------------cut here---------------end--------------->8---

It now runs much faster:

--8<---------------cut here---------------start------------->8---
$ time+ zstd -cdk /tmp/chromium-98.0.4758.102.tar.zst > /dev/null
cpu: 98%, mem: 10560 KiB, wall: 0:09.56, sys: 0.37, usr: 9.06
--8<---------------cut here---------------end--------------->8---

--8<---------------cut here---------------start------------->8---
$ time+ guile ~/src/guile-zstd/benchmark.scm
cpu: 100%, mem: 25152 KiB, wall: 0:11.69, sys: 0.38, usr: 11.30
--8<---------------cut here---------------end--------------->8---

So guile-zstd was about 20% slower, not too far.

For completeness, here's the same benchmark adjusted for guile-zlib:

--8<---------------cut here---------------start------------->8---
(use-modules (ice-9 binary-ports)
             (ice-9 match)
             (rnrs bytevectors)
             (zlib))

(define MiB (expt 2 20))
(define block-size (* 4 MiB))
(define bv (make-bytevector block-size))
(define input-file "/tmp/chromium-98.0.4758.102.tar.gz")

(define (run)
  (call-with-input-file input-file
    (lambda (port)
      (call-with-gzip-input-port port
        (lambda (input)
          (while (not (eof-object?
                       (get-bytevector-n! input bv 0 block-size)))))))))

(run)
--8<---------------cut here---------------end--------------->8---

--8<---------------cut here---------------start------------->8---
$ time+ guile ~/src/guile-zstd/benchmark-zlib.scm
cpu: 86%, mem: 14552 KiB, wall: 0:23.50, sys: 1.09, usr: 19.15
--8<---------------cut here---------------end--------------->8---

--8<---------------cut here---------------start------------->8---
$ time+ gunzip -ck /tmp/chromium-98.0.4758.102.tar.gz > /dev/null
cpu: 98%, mem: 2304 KiB, wall: 0:35.99, sys: 0.60, usr: 34.99
--8<---------------cut here---------------end--------------->8---

Surprisingly, here guile-zlib appears to be faster than the 'gunzip'
command; guile-zstd is about twice as fast to decompress this 4 GiB
something archive (compressed with zstd at level 19).

So, it seems the foundation we're building on is sane after all.  This
suggests that compression is not the bottleneck when generating the man
pages database, probably because it only needs to read the first few
bytes of each compressed manpage to gather the information it needs, and
that the rest is more expensive compared to that (such as
string-tokenize'ing the lines read to parse the data).

To be continued...

Thanks!

Maxim


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-29 10:30     ` Ludovic Courtès
  2022-03-30 14:49       ` Maxim Cournoyer
@ 2022-03-30 16:16       ` Jonathan McHugh
  1 sibling, 0 replies; 10+ messages in thread
From: Jonathan McHugh @ 2022-03-30 16:16 UTC (permalink / raw)
  To: Maxim Cournoyer, Ludovic Courtès; +Cc: guix-devel

Hi Maxim,

Out of interest, will a zstd dictionary be (eventually) utilised as a strategy for further reducing compression and decompression speeds?

```
The compression library Zstandard (also known as "Zstd") has the ability to create an external "dictionary" from a set of training files which can be used to more efficiently (in terms of compression and decompression speed and also in terms of compression ratio) compress files of the same type as the training files. For example, if a dictionary is "trained" on an example set of email messages, anyone with access to the dictionary will be able to more efficiently compress another email file. The trick is that the commonalities are kept in the dictionary file, and, therefore, anyone wishing to decompress the email must have already had that same dictionary sent to them.[2] 
```
http://fileformats.archiveteam.org/wiki/Zstandard_dictionary

I appreciate it may confuse your piecemeal benchmarking (certainly at this stage) but I would assume that creating a dictionary (or dictionaries, say covering each Guix package category for linguistic overlaps) for manpages would further improve zstd speeds.

HTH,

====================
Jonathan McHugh
indieterminacy@libre.brussels

March 30, 2022 4:49 PM, "Maxim Cournoyer" <maxim.cournoyer@gmail.com> wrote:

> Hi Ludovic,
> 
> Ludovic Courtès <ludo@gnu.org> writes:
> 
> [...]
> 
>> To isolate the problem, you could allocate the 4 MiB buffer outside of
>> the loop and use ‘get-bytevector-n!’, and also remove code that writes
>> to ‘output’.
> 
> I've adjusted the benchmark like so:
> 
> --8<---------------cut here---------------start------------->8---
> (use-modules (ice-9 binary-ports)
> (ice-9 match)
> (rnrs bytevectors)
> (zstd))
> 
> (define MiB (expt 2 20))
> (define block-size (* 4 MiB))
> (define bv (make-bytevector block-size))
> (define input-file "/tmp/chromium-98.0.4758.102.tar.zst")
> 
> (define (run)
> (call-with-input-file input-file
> (lambda (port)
> (call-with-zstd-input-port port
> (lambda (input)
> (while (not (eof-object?
> (get-bytevector-n! input bv 0 block-size)))))))))
> 
> (run)
> --8<---------------cut here---------------end--------------->8---
> 
> It now runs much faster:
> 
> --8<---------------cut here---------------start------------->8---
> $ time+ zstd -cdk /tmp/chromium-98.0.4758.102.tar.zst > /dev/null
> cpu: 98%, mem: 10560 KiB, wall: 0:09.56, sys: 0.37, usr: 9.06
> --8<---------------cut here---------------end--------------->8---
> 
> --8<---------------cut here---------------start------------->8---
> $ time+ guile ~/src/guile-zstd/benchmark.scm
> cpu: 100%, mem: 25152 KiB, wall: 0:11.69, sys: 0.38, usr: 11.30
> --8<---------------cut here---------------end--------------->8---
> 
> So guile-zstd was about 20% slower, not too far.
> 
> For completeness, here's the same benchmark adjusted for guile-zlib:
> 
> --8<---------------cut here---------------start------------->8---
> (use-modules (ice-9 binary-ports)
> (ice-9 match)
> (rnrs bytevectors)
> (zlib))
> 
> (define MiB (expt 2 20))
> (define block-size (* 4 MiB))
> (define bv (make-bytevector block-size))
> (define input-file "/tmp/chromium-98.0.4758.102.tar.gz")
> 
> (define (run)
> (call-with-input-file input-file
> (lambda (port)
> (call-with-gzip-input-port port
> (lambda (input)
> (while (not (eof-object?
> (get-bytevector-n! input bv 0 block-size)))))))))
> 
> (run)
> --8<---------------cut here---------------end--------------->8---
> 
> --8<---------------cut here---------------start------------->8---
> $ time+ guile ~/src/guile-zstd/benchmark-zlib.scm
> cpu: 86%, mem: 14552 KiB, wall: 0:23.50, sys: 1.09, usr: 19.15
> --8<---------------cut here---------------end--------------->8---
> 
> --8<---------------cut here---------------start------------->8---
> $ time+ gunzip -ck /tmp/chromium-98.0.4758.102.tar.gz > /dev/null
> cpu: 98%, mem: 2304 KiB, wall: 0:35.99, sys: 0.60, usr: 34.99
> --8<---------------cut here---------------end--------------->8---
> 
> Surprisingly, here guile-zlib appears to be faster than the 'gunzip'
> command; guile-zstd is about twice as fast to decompress this 4 GiB
> something archive (compressed with zstd at level 19).
> 
> So, it seems the foundation we're building on is sane after all. This
> suggests that compression is not the bottleneck when generating the man
> pages database, probably because it only needs to read the first few
> bytes of each compressed manpage to gather the information it needs, and
> that the rest is more expensive compared to that (such as
> string-tokenize'ing the lines read to parse the data).
> 
> To be continued...
> 
> Thanks!
> 
> Maxim


^ permalink raw reply	[flat|nested] 10+ messages in thread

* Re: Profiling of man-db database generation with zlib vs zstd
  2022-03-28  3:49   ` Maxim Cournoyer
  2022-03-29 10:30     ` Ludovic Courtès
@ 2022-03-31 17:13     ` Ludovic Courtès
  1 sibling, 0 replies; 10+ messages in thread
From: Ludovic Courtès @ 2022-03-31 17:13 UTC (permalink / raw)
  To: Maxim Cournoyer; +Cc: guix-devel

Hi!

I did a similar experiment as you did, but using the GCC tarball (I was
too lazy to wait for ungoogled-chromium’s tarball), like so:

--8<---------------cut here---------------start------------->8---
$ xz -d < /gnu/store/x043r7crzd0p0p5cfky8r6hwsxknhkk0-gcc-11.2.0.tar.xz | zstd -19 > /tmp/gcc.zst
$ xz -d < /gnu/store/x043r7crzd0p0p5cfky8r6hwsxknhkk0-gcc-11.2.0.tar.xz | gzip -9 > /tmp/gcc.gz
$ du -h /tmp/gcc.{zst,gz}
81M     /tmp/gcc.zst
128M    /tmp/gcc.gz
--8<---------------cut here---------------end--------------->8---

The code (the inner loop is pure decompression, no allocation, no I/O):

--8<---------------cut here---------------start------------->8---
(use-modules (zstd)
             (zlib)
             (rnrs bytevectors)
             (ice-9 binary-ports)
             (ice-9 match)
             (ice-9 time))

(define bv (make-bytevector (* 4 (expt 2 20))))

(define (dump port)
  (let loop ()
    (match (get-bytevector-n! port bv
                              0 (bytevector-length bv))
      ((? eof-object?) #t)
      (n (loop)))))

(pk 'zlib)
(call-with-gzip-input-port (open-input-file "/tmp/gcc.gz")
  (lambda (port) (time (dump port))))

(pk 'zst)
(call-with-zstd-input-port (open-input-file "/tmp/gcc.zst")
  (lambda (port) (time (dump port))))
--8<---------------cut here---------------end--------------->8---

The result shows that zstd decompression is ~60% faster than gzip
decompression:

--8<---------------cut here---------------start------------->8---
$ guile ~/src/guix-debugging/decompress.scm

;;; (zlib)
clock utime stime cutime cstime gctime
 2.15  2.11  0.03   0.00   0.00   0.00

;;; (zst)
clock utime stime cutime cstime gctime
 0.80  0.77  0.03   0.00   0.00   0.00
--8<---------------cut here---------------end--------------->8---

Are you observing something similar?

Ludo’.


^ permalink raw reply	[flat|nested] 10+ messages in thread

end of thread, other threads:[~2022-03-31 17:13 UTC | newest]

Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-03-22 19:09 Profiling of man-db database generation with zlib vs zstd Maxim Cournoyer
2022-03-24 21:37 ` Ludovic Courtès
2022-03-26  3:22   ` Maxim Cournoyer
2022-03-27  3:44     ` Maxim Cournoyer
2022-03-29 10:22       ` Ludovic Courtès
2022-03-28  3:49   ` Maxim Cournoyer
2022-03-29 10:30     ` Ludovic Courtès
2022-03-30 14:49       ` Maxim Cournoyer
2022-03-30 16:16       ` Jonathan McHugh
2022-03-31 17:13     ` Ludovic Courtès

Code repositories for project(s) associated with this public inbox

	https://git.savannah.gnu.org/cgit/guix.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).