bug#26942: [PATCH] Add Add elapsed time to manual-database hook to output message (was: Performance of the man page database generation)

[Maxim Cournoyer <maxim.cournoyer@gmail.com>]

[-- Attachment #1: Type: text/plain, Size: 581 bytes --]

Hi myglc2,

I'm sending a patch which implements the following:

--8<---------------cut here---------------start------------->8---
guix build --check /gnu/store/yx1hdcvyc3agv7bwbxm7jv7zlm6ibzqr-manual-database.drv
[...]
Creating manual page database for 62 packages... done in 35.112 s
--8<---------------cut here---------------end--------------->8---

The change improves the message output by the manual-database hook with
the addition is the closing of the message with a "done in x.xxx s".

Thanks to myglc2 for providing a snippet and ideas about how to improve this.

Maxim


[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-profiles-Add-elapsed-time-to-manual-database-hook-to.patch --]
[-- Type: text/x-patch, Size: 2090 bytes --]

From 3ec52305f6a1836b42e34b4dc194c16afb1592a2 Mon Sep 17 00:00:00 2001
From: Maxim Cournoyer <maxim.cournoyer@gmail.com>
Date: Mon, 15 May 2017 09:05:48 -0700
Subject: [PATCH] profiles: Add elapsed time to manual-database hook to output
 message.

* guix/profiles.scm (manual-database): Add elapsed time to manual-database
hook to output message.
---
 guix/profiles.scm | 18 +++++++++++++-----
 1 file changed, 13 insertions(+), 5 deletions(-)

diff --git a/guix/profiles.scm b/guix/profiles.scm
index eb172ef450..6733f105e3 100644
--- a/guix/profiles.scm
+++ b/guix/profiles.scm
@@ -957,6 +957,7 @@ the entries in MANIFEST."
     #~(begin
         (use-modules (guix build utils)
                      (srfi srfi-1)
+                     (srfi srfi-19)
                      (srfi srfi-26))
 
         (define entries
@@ -1011,16 +1012,23 @@ the entries in MANIFEST."
         (mkdir-p man-directory)
         (setenv "MANPATH" (string-join entries ":"))
 
-        (format #t "creating manual page database for ~a packages...~%"
+        (format #t "Creating manual page database for ~a packages... "
                 (length entries))
         (force-output)
-
-        (zero? (system* #+(file-append man-db "/bin/mandb")
-                        "--quiet" "--create"
-                        "-C" "man_db.conf"))))
+        (let* ((start-time (current-time))
+               (exit-status (system* #+(file-append man-db "/bin/mandb")
+                                    "--quiet" "--create"
+                                    "-C" "man_db.conf"))
+               (duration (time-difference (current-time) start-time)))
+          (format #t "done in ~,3f s~%"
+                  (+ (time-second duration)
+                     (* (time-nanosecond duration) (expt 10 -9))))
+          (force-output)
+          (zero? exit-status))))
 
   (gexp->derivation "manual-database" build
                     #:modules '((guix build utils)
+                                (srfi srfi-19)
                                 (srfi srfi-26))
                     #:local-build? #t))
 
-- 
2.12.2


[-- Attachment #3: Type: text/plain, Size: 3895 bytes --]


--
For reference, the last bit of conversation which occured on
guix-devel regarding this was:

myglc2 <myglc2@gmail.com> writes:

[...]

> Hi Maxim and Ludo’,
>
> I hacked profiles.scm (please see git diff below) so that start and end
> seconds appear in the message like this:
>
> creating manual page database for 23 packages...1494773268...1494773275 DONE
>
> I tested a few cases and man-db typically takes only a few seconds.  It
> only _appears_ to take a long time because other processing occurs after
> the man-db command.
>
> So, I suggest either ...
>
> 1) delete the message altogether, or
> 2) close the message with a "DONE"
>
> SORRY for the run-around. In my defense, when I first raised the
> question I did suggest the idea of closing the message:
>

No need to be sorry; improvements/ideas are always welcome! :)

> http://lists.gnu.org/archive/html/guix-devel/2017-04/msg00196.html
>
> HTH, George
>
> g1@g1 ~/src/guix [env]$ git diff
> diff --git a/guix/profiles.scm b/guix/profiles.scm
> index eb172ef45..4dbf44a81 100644
> --- a/guix/profiles.scm
> +++ b/guix/profiles.scm
> @@ -1011,13 +1011,15 @@ the entries in MANIFEST."
>          (mkdir-p man-directory)
>          (setenv "MANPATH" (string-join entries ":"))
>  
> -        (format #t "creating manual page database for ~a packages...~%"
> -                (length entries))
> +        (format #t "creating manual page database for ~a packages...~a"
> +                (length entries)(current-time))
>          (force-output)
>  
>          (zero? (system* #+(file-append man-db "/bin/mandb")
>                          "--quiet" "--create"
> -                        "-C" "man_db.conf"))))
> +                        "-C" "man_db.conf"))
> +        (format #t "...~a DONE~%" (current-time))
> +        (force-output)))
>  
>    (gexp->derivation "manual-database" build
>                      #:modules '((guix build utils)
> g1@g1 ~/src/guix [env]$ 

I'd suggest leaving closing the message on the same line, maybe with
something like:


--8<---------------cut here---------------end--------------->8---
diff --git a/guix/profiles.scm b/guix/profiles.scm
index eb172ef450..6733f105e3 100644
--- a/guix/profiles.scm
+++ b/guix/profiles.scm
@@ -957,6 +957,7 @@ the entries in MANIFEST."
     #~(begin
         (use-modules (guix build utils)
                      (srfi srfi-1)
+                     (srfi srfi-19)
                      (srfi srfi-26))
 
         (define entries
@@ -1011,16 +1012,23 @@ the entries in MANIFEST."
         (mkdir-p man-directory)
         (setenv "MANPATH" (string-join entries ":"))
 
-        (format #t "creating manual page database for ~a packages...~%"
+        (format #t "Creating manual page database for ~a packages... "
                 (length entries))
         (force-output)
-
-        (zero? (system* #+(file-append man-db "/bin/mandb")
-                        "--quiet" "--create"
-                        "-C" "man_db.conf"))))
+        (let* ((start-time (current-time))
+               (exit-status (system* #+(file-append man-db "/bin/mandb")
+                                    "--quiet" "--create"
+                                    "-C" "man_db.conf"))
+               (duration (time-difference (current-time) start-time)))
+          (format #t "done in ~,3f s~%"
+                  (+ (time-second duration)
+                     (* (time-nanosecond duration) (expt 10 -9))))
+          (force-output)
+          (zero? exit-status))))
 
   (gexp->derivation "manual-database" build
                     #:modules '((guix build utils)
+                                (srfi srfi-19)
                                 (srfi srfi-26))
                     #:local-build? #t))
--8<---------------cut here---------------end--------------->8---