Re: Guile's time execution issues

["Aleix Conchillo Flaqué" <aconchillo@gmail.com>]

On Sun, Apr 26, 2020 at 10:16 AM Ludovic Courtès <ludo@gnu.org> wrote:

> Bon dia!
>
>
Bon dia! And bon jour! :-D

> Aleix Conchillo Flaqué <aconchillo@gmail.com> skribis:
>
> > I was trying to get some guile-json performance times loading large JSON
> > file. However, I'm getting increasing numbers at each run, so I'm
> wondering
> > if I'm doing something wrong. Below you can see how the first run took
> > 19.95s and then running the same command kept increasing.
> >
> > I'm running Guile 2.2.7 on macOS Catalina 10.15.3.
> >
> > scheme@(guile-user)> (use-modules (json))
> > scheme@(guile-user)> ,t (define a (call-with-input-file
> > "/Users/aleix/Downloads/large-file.json" (lambda (port) (json->scm
> port))))
> > ;; 19.956429s real time, 87.100982s run time.  75.270202s spent in GC.
> > ;; 26.173179s real time, 143.645265s run time.  131.022631s spent in GC.
> > ;; 28.193926s real time, 154.758375s run time.  141.697236s spent in GC.
> > ;; 29.044218s real time, 160.745984s run time.  147.449073s spent in GC.
> > ;; 30.480873s real time, 170.855527s run time.  157.332793s spent in GC.
> > ;; 30.555700s real time, 172.938278s run time.  159.468737s spent in GC.
> > ;; 32.190478s real time, 172.807551s run time.  158.905645s spent in GC.
>
> Could this have to do with <https://issues.guix.gnu.org/issue/40194>?
>
>
Honestly, I have no idea... :-(

Could you check if that happens with 3.0.2?  (Or suggest a
> ‘large-file.json’ to use.  :-))
>
>
Sure! I suggested a JSON, it was hidden at the end of my first message ;-).
This is the one:

   https://github.com/json-iterator/test-data/blob/master/large-file.json

So, bad and good news for Guile 3.0.2. I'm trying it inside Docker using
this image https://hub.docker.com/r/schemers/guile.

On guile-json 3.5.0 (still using (string-append)) the first execution time
goes from 19 seconds to 42 seconds. Then, the times keep increasing as in
version 2.2.7 but numbers are much bigger:

# ./env guile
GNU Guile 3.0.2
Copyright (C) 1995-2020 Free Software Foundation, Inc.

Guile comes with ABSOLUTELY NO WARRANTY; for details type `,show w'.
This program is free software, and you are welcome to redistribute it
under certain conditions; type `,show c' for details.

Enter `,help' for help.
scheme@(guile-user)> (use-modules (json))
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 42.015887s real time, 42.059462s run time.  32.838460s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 56.228837s real time, 56.176989s run time.  46.112349s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 63.472869s real time, 63.383118s run time.  52.642226s spent in GC.

The good news is that on master branch I don't use (string-append) anymore
and it goes from 19 seconds (in 2.2.7) to ~6 seconds (both in 2.2.7 and
3.0.2).

❯ ./env guile
GNU Guile 2.2.7
Copyright (C) 1995-2019 Free Software Foundation, Inc.

Guile comes with ABSOLUTELY NO WARRANTY; for details type `,show w'.
This program is free software, and you are welcome to redistribute it
under certain conditions; type `,show c' for details.

Enter `,help' for help.
scheme@(guile-user)> (use-modules (json))
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.635275s real time, 11.126605s run time.  5.119203s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.856995s real time, 12.605237s run time.  6.476064s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.556502s real time, 10.542702s run time.  4.550531s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.396581s real time, 9.638931s run time.  3.707881s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.293497s real time, 8.944718s run time.  3.055733s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.249073s real time, 8.938264s run time.  3.099037s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.168000s real time, 8.557252s run time.  2.772902s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.206124s real time, 7.920464s run time.  2.022655s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.404214s real time, 8.412361s run time.  2.402077s spent in GC.

And actually Guile 3.0.2 seems a bit slower at the beginning but then for
some reason times go down until they seem to stabilize (I have tried it a
couple of times and it does the same) and then it seems a bit faster than
2.2.7:

# ./env guile
GNU Guile 3.0.2
Copyright (C) 1995-2020 Free Software Foundation, Inc.

Guile comes with ABSOLUTELY NO WARRANTY; for details type `,show w'.
This program is free software, and you are welcome to redistribute it
under certain conditions; type `,show c' for details.

Enter `,help' for help.
scheme@(guile-user)> (use-modules (json))
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.961477s real time, 6.973492s run time.  2.294030s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 7.450862s real time, 7.422345s run time.  2.718710s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.438989s real time, 6.399829s run time.  1.896063s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 6.097962s real time, 6.070055s run time.  1.540690s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 5.650008s real time, 5.668240s run time.  1.272017s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 5.754515s real time, 5.748386s run time.  1.275179s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 5.760096s real time, 5.755418s run time.  1.310558s spent in GC.
scheme@(guile-user)> ,t (define a (call-with-input-file "large-file.json"
(lambda (port) (json->scm port))))
;; 5.745274s real time, 5.739386s run time.  1.356917s spent in GC.

Let me know if you want me to test anything else.



> Thanks in advance!
>
>
Thank you!

Aleix