[PATCH] find-debuginfo: unless -q -q, print messages what big steps we are at

[PATCH] find-debuginfo: unless -q -q, print messages what big steps we are at

[Denys Vlasenko]

For a reader of rpmbuild's log, it's rather unclear what find-debuginfo
is doing. It used to be too verbose, "extracting debug info from FILE"
for every file, and while this can be suppressed now, we still end up
with something semi-mysterious like this:

...
extracting debug info from /builddir/build/BUILDROOT/xyz
gdb-add-index: No index was created for /builddir/build/BUILDROOT/xyz
gdb-add-index: [Was there no debuginfo? Was there already an index?]
symlinked /usr/lib/debug/usr/lib64/libcpupower.so.0.0.1.debug to /usr/lib/debug/usr/lib64/libcpupower.so.debug
symlinked /usr/lib/debug/usr/lib64/libcpupower.so.0.0.1.debug to /usr/lib/debug/usr/lib64/libcpupower.so.0.debug
cpio: binutils-2.30/bfd: Cannot stat: No such file or directory
cpio: binutils-2.30/bfd/aout-target.h: Cannot stat: No such file or directory
cpio: binutils-2.30/bfd/aoutx.h: Cannot stat: No such file or directory
cpio: binutils-2.30/bfd/archive.c: Cannot stat: No such file or directory
cpio: binutils-2.30/bfd/archive64.c: Cannot stat: No such file or directory
...
775655 blocks
+ /usr/lib/rpm/check-buildroot
+ /usr/lib/rpm/redhat/brp-ldconfig
...

The reader is left confused. "What these cpio errors are about?
Why those sources are not found?" (Well, because not every source
name extracted by 'debugedit -l' has to exist, but this requires
considerable digging aroung to understand).

We can give a few messages explaining what general steps we go through:

    Extracting debug info from N files
    DWARF-compressing N files
    Creating .debug symlinks for symlinks to ELF files
    Copying sources found by 'debugedit -l'

This is also useful to get a feeling which steps are time consuming.
Kernel builds often need to investigate this aspect. To help a bit more,
add "find-debuginfo: starting" and "find-debuginfo: done" messages too.

This patch adds these messages.

Two -q -q options suppress these messages too.

Signed-off-by: Denys Vlasenko <dvlasenk@redhat.com>
---
 scripts/find-debuginfo.in | 16 ++++++++++++++--
 1 file changed, 14 insertions(+), 2 deletions(-)

diff --git a/scripts/find-debuginfo.in b/scripts/find-debuginfo.in
index e7ac095..b76edaf 100755
--- a/scripts/find-debuginfo.in
+++ b/scripts/find-debuginfo.in
@@ -94,7 +94,8 @@ will be called /usr/debug/src/<BASE>.  This makes sure the debug source
 dirs are unique between package version, release and achitecture (Use
 --unique-debug-src-base "%{name}-%{VERSION}-%{RELEASE}.%{_arch}")
 
-The -q or --quiet flag silences non-error output from the script.
+The -q or --quiet flag silences verbose output from the script.
+Given twice, silences all non-error output from the script.
 
 All file names in switches are relative to builddir ('.' if not given).
 EOF
@@ -148,8 +149,10 @@ n_jobs=1
 # exit early on --version or --help
 done=false
 
-# silence non-error output
+# silence verbose output
 quiet=false
+# silence non-error output
+quiet2=false
 
 BUILDDIR=.
 out=debugfiles.list
@@ -245,6 +248,7 @@ while [ $# -gt 0 ]; do
     shift
     ;;
   -q|--quiet)
+    $quiet && quiet2=true
     quiet=true
     ;;
   --version)
@@ -289,6 +293,8 @@ if [ "$strip_g" = "true" ] && [ "$strip_glibs" = "true" ]; then
   exit 2
 fi
 
+$quiet2 || echo "find-debuginfo: starting" 2>&1
+
 i=0
 while ((i < nout)); do
   outs[$i]="$BUILDDIR/${outs[$i]}"
@@ -549,6 +555,7 @@ run_job()
 }
 
 n_files=$(wc -l <"$temp/primary")
+$quiet2 || echo "Extracting debug info from $n_files files" 2>&1
 if [ $n_jobs -gt $n_files ]; then
   n_jobs=$n_files
 fi
@@ -587,6 +594,7 @@ if $run_dwz \
    && [ -d "${RPM_BUILD_ROOT}/usr/lib/debug" ]; then
   readarray dwz_files < <(cd "${RPM_BUILD_ROOT}/usr/lib/debug"; find -type f -name \*.debug | LC_ALL=C sort)
   if [ ${#dwz_files[@]} -gt 0 ]; then
+    $quiet2 || echo "DWARF-compressing ${#dwz_files[@]} files" 2>&1
     $quiet || size_before=$(du -sk ${RPM_BUILD_ROOT}/usr/lib/debug | cut -f1)
     dwz_multifile_name="${RPM_PACKAGE_NAME}-${RPM_PACKAGE_VERSION}-${RPM_PACKAGE_RELEASE}.${RPM_ARCH}"
     dwz_multifile_suffix=
@@ -625,6 +633,7 @@ fi
 
 # For each symlink whose target has a .debug file,
 # make a .debug symlink to that file.
+$quiet2 || echo "Creating .debug symlinks for symlinks to ELF files" 2>&1
 find "$RPM_BUILD_ROOT" ! -path "${debugdir}/*" -type l -print |
 while read f
 do
@@ -646,6 +655,7 @@ if [ -s "$SOURCEFILE" ]; then
     debug_dest_name="/usr/src/debug/${unique_debug_src_base}"
   fi
 
+  $quiet2 || echo "Copying sources found by 'debugedit -l' to ${debug_dest_name}" 2>&1
   mkdir -p "${RPM_BUILD_ROOT}${debug_dest_name}"
   # Filter out anything compiler generated which isn't a source file.
   # e.g. <internal>, <built-in>, <__thread_local_inner macros>.
@@ -761,3 +771,5 @@ if ((nout > 0)); then
   cat "$LISTFILE" >> "${LISTFILE}.new"
   mv "${LISTFILE}.new" "$LISTFILE"
 fi
+
+$quiet2 || echo "find-debuginfo: done" 2>&1
-- 
2.37.2

Re: [PATCH] find-debuginfo: unless -q -q, print messages what big steps we are at

[Mark Wielaard]

Hi Denys,

On Thu, Jun 22, 2023 at 03:31:03PM +0200, Denys Vlasenko wrote:
> For a reader of rpmbuild's log, it's rather unclear what find-debuginfo
> is doing. It used to be too verbose, "extracting debug info from FILE"
> for every file, and while this can be suppressed now, we still end up
> with something semi-mysterious like this:
> 
> ...
> extracting debug info from /builddir/build/BUILDROOT/xyz
> gdb-add-index: No index was created for /builddir/build/BUILDROOT/xyz
> gdb-add-index: [Was there no debuginfo? Was there already an index?]
> symlinked /usr/lib/debug/usr/lib64/libcpupower.so.0.0.1.debug to /usr/lib/debug/usr/lib64/libcpupower.so.debug
> symlinked /usr/lib/debug/usr/lib64/libcpupower.so.0.0.1.debug to /usr/lib/debug/usr/lib64/libcpupower.so.0.debug
> cpio: binutils-2.30/bfd: Cannot stat: No such file or directory
> cpio: binutils-2.30/bfd/aout-target.h: Cannot stat: No such file or directory
> cpio: binutils-2.30/bfd/aoutx.h: Cannot stat: No such file or directory
> cpio: binutils-2.30/bfd/archive.c: Cannot stat: No such file or directory
> cpio: binutils-2.30/bfd/archive64.c: Cannot stat: No such file or directory
> ...
> 775655 blocks
> + /usr/lib/rpm/check-buildroot
> + /usr/lib/rpm/redhat/brp-ldconfig
> ...
> 
> The reader is left confused. "What these cpio errors are about?
> Why those sources are not found?" (Well, because not every source
> name extracted by 'debugedit -l' has to exist, but this requires
> considerable digging aroung to understand).
> 
> We can give a few messages explaining what general steps we go through:
> 
>     Extracting debug info from N files
>     DWARF-compressing N files
>     Creating .debug symlinks for symlinks to ELF files
>     Copying sources found by 'debugedit -l'
> 
> This is also useful to get a feeling which steps are time consuming.
> Kernel builds often need to investigate this aspect. To help a bit more,
> add "find-debuginfo: starting" and "find-debuginfo: done" messages too.
> 
> This patch adds these messages.
> 
> Two -q -q options suppress these messages too.

I like this idea, but I am wondering if instead of -q -q we should
have a -v,--verbose flag for the very verbose output. Then this
explanary output could be the default. And -q,--quiet would suppress
even those message.

Cheers,

Mark

Re: [PATCH] find-debuginfo: unless -q -q, print messages what big steps we are at

[Mark Wielaard]

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

Hi Denys,

On Thu, 2023-06-29 at 16:13 +0200, Mark Wielaard wrote:
> > We can give a few messages explaining what general steps we go through:
> > 
> >     Extracting debug info from N files
> >     DWARF-compressing N files
> >     Creating .debug symlinks for symlinks to ELF files
> >     Copying sources found by 'debugedit -l'
> > 
> > This is also useful to get a feeling which steps are time consuming.
> > Kernel builds often need to investigate this aspect. To help a bit more,
> > add "find-debuginfo: starting" and "find-debuginfo: done" messages too.
> > 
> > This patch adds these messages.
> > 
> > Two -q -q options suppress these messages too.
> 
> I like this idea, but I am wondering if instead of -q -q we should
> have a -v,--verbose flag for the very verbose output. Then this
> explanary output could be the default. And -q,--quiet would suppress
> even those message.

So this is what I was thinking. What do you think?
https://code.wildebeest.org/git/user/mjw/debugedit/commit/?h=verbose

Thanks,

Mark

[-- Attachment #2: Type: text/x-patch, Size: 7627 bytes --]

From 2eecc4ef19e0a31c56fc9912d8e7a9cb325db33b Mon Sep 17 00:00:00 2001
From: Denys Vlasenko <dvlasenk@redhat.com>
Date: Thu, 22 Jun 2023 15:31:03 +0200
Subject: [PATCH] find-debuginfo: Add -v,--verbose for per file messages

Only print messages what big steps we are at without --verbose.

For a reader of rpmbuild's log, it's rather unclear what find-debuginfo
is doing. It used to be too verbose, "extracting debug info from FILE"
for every file, and while this can be suppressed now, we still end up
with something semi-mysterious like this:

...
extracting debug info from /builddir/build/BUILDROOT/xyz
gdb-add-index: No index was created for /builddir/build/BUILDROOT/xyz
gdb-add-index: [Was there no debuginfo? Was there already an index?]
symlinked /usr/lib/debug/usr/lib64/libcpupower.so.0.0.1.debug to /usr/lib/debug/usr/lib64/libcpupower.so.debug
symlinked /usr/lib/debug/usr/lib64/libcpupower.so.0.0.1.debug to /usr/lib/debug/usr/lib64/libcpupower.so.0.debug
cpio: binutils-2.30/bfd: Cannot stat: No such file or directory
cpio: binutils-2.30/bfd/aout-target.h: Cannot stat: No such file or directory
cpio: binutils-2.30/bfd/aoutx.h: Cannot stat: No such file or directory
cpio: binutils-2.30/bfd/archive.c: Cannot stat: No such file or directory
cpio: binutils-2.30/bfd/archive64.c: Cannot stat: No such file or directory
...
775655 blocks
+ /usr/lib/rpm/check-buildroot
+ /usr/lib/rpm/redhat/brp-ldconfig
...

The reader is left confused. "What these cpio errors are about?
Why those sources are not found?" (Well, because not every source
name extracted by 'debugedit -l' has to exist, but this requires
considerable digging aroung to understand).

We can give a few messages explaining what general steps we go through:

    Extracting debug info from N files
    DWARF-compressing N files
    Creating .debug symlinks for symlinks to ELF files
    Copying sources found by 'debugedit -l'

This is also useful to get a feeling which steps are time consuming.
Kernel builds often need to investigate this aspect. To help a bit more,
add "find-debuginfo: starting" and "find-debuginfo: done" messages too.

This patch adds these messages.
The -q options suppress these messages too.

It also adds a --verbose flag to print per file messages.
Those per file messages are now suppressed by default and
only the general step messages are show. Unless -q is given,
which suppresses all non-error output.

Signed-off-by: Denys Vlasenko <dvlasenk@redhat.com>
Signed-off-by: Mark Wielaard <mark@klomp.org>
---
 scripts/find-debuginfo.in | 36 +++++++++++++++++++++++++++---------
 1 file changed, 27 insertions(+), 9 deletions(-)

diff --git a/scripts/find-debuginfo.in b/scripts/find-debuginfo.in
index e7ac095..9cfb701 100755
--- a/scripts/find-debuginfo.in
+++ b/scripts/find-debuginfo.in
@@ -26,7 +26,7 @@ Usage: find-debuginfo [OPTION]... [builddir]
 automagically generates debug info and file lists
 
 Options:
-[--strict-build-id] [-g] [-r] [-m] [-i] [-n] [-q]
+[--strict-build-id] [-g] [-r] [-m] [-i] [-n] [-q] [-v]
 [--keep-section SECTION] [--remove-section SECTION]
 [--g-libs]
 [-j N] [--jobs N]
@@ -94,7 +94,9 @@ will be called /usr/debug/src/<BASE>.  This makes sure the debug source
 dirs are unique between package version, release and achitecture (Use
 --unique-debug-src-base "%{name}-%{VERSION}-%{RELEASE}.%{_arch}")
 
-The -q or --quiet flag silences non-error output from the script.
+The -q or --quiet flag silences all non-error output from the script.
+The -v or --verbose flag add more output for all files processed.
+When neither -q or -v is given then only output for each pass is given.
 
 All file names in switches are relative to builddir ('.' if not given).
 EOF
@@ -148,9 +150,12 @@ n_jobs=1
 # exit early on --version or --help
 done=false
 
-# silence non-error output
+# silence all output
 quiet=false
 
+# add more non-error output
+verbose=false
+
 BUILDDIR=.
 out=debugfiles.list
 srcout=
@@ -246,6 +251,11 @@ while [ $# -gt 0 ]; do
     ;;
   -q|--quiet)
     quiet=true
+    verbose=false
+    ;;
+  -v|--verbose)
+    quiet=false
+    verbose=true
     ;;
   --version)
     echo "find-debuginfo @VERSION@"
@@ -289,6 +299,8 @@ if [ "$strip_g" = "true" ] && [ "$strip_glibs" = "true" ]; then
   exit 2
 fi
 
+$quiet || echo "find-debuginfo: starting" 2>&1
+
 i=0
 while ((i < nout)); do
   outs[$i]="$BUILDDIR/${outs[$i]}"
@@ -445,7 +457,7 @@ do_file()
   get_debugfn "$f"
   [ -f "${debugfn}" ] && return
 
-  $quiet || echo "extracting debug info from $f"
+  $verbose && echo "extracting debug info from $f"
   # See also cpio SOURCEFILE copy. Directories must match up.
   debug_base_name="$RPM_BUILD_DIR"
   debug_dest_name="/usr/src/debug"
@@ -521,7 +533,7 @@ do_file()
     grep "^$inum " "$temp/linked" | while read inum linked; do
       link=$debugfn
       get_debugfn "$linked"
-      $quiet || echo "hard linked $link to $debugfn"
+      $verbose && echo "hard linked $link to $debugfn"
       mkdir -p "$(dirname "$debugfn")" && ln -nf "$link" "$debugfn"
     done
   fi
@@ -549,6 +561,7 @@ run_job()
 }
 
 n_files=$(wc -l <"$temp/primary")
+$quiet || echo "Extracting debug info from $n_files files" 2>&1
 if [ $n_jobs -gt $n_files ]; then
   n_jobs=$n_files
 fi
@@ -587,7 +600,8 @@ if $run_dwz \
    && [ -d "${RPM_BUILD_ROOT}/usr/lib/debug" ]; then
   readarray dwz_files < <(cd "${RPM_BUILD_ROOT}/usr/lib/debug"; find -type f -name \*.debug | LC_ALL=C sort)
   if [ ${#dwz_files[@]} -gt 0 ]; then
-    $quiet || size_before=$(du -sk ${RPM_BUILD_ROOT}/usr/lib/debug | cut -f1)
+    $quiet || echo "DWARF-compressing ${#dwz_files[@]} files" 2>&1
+    $verbose && size_before=$(du -sk ${RPM_BUILD_ROOT}/usr/lib/debug | cut -f1)
     dwz_multifile_name="${RPM_PACKAGE_NAME}-${RPM_PACKAGE_VERSION}-${RPM_PACKAGE_RELEASE}.${RPM_ARCH}"
     dwz_multifile_suffix=
     dwz_multifile_idx=0
@@ -611,8 +625,8 @@ if $run_dwz \
       echo >&2 "*** ERROR: DWARF compression requested, but no dwz installed"
       exit 2
     fi
-    $quiet || size_after=$(du -sk ${RPM_BUILD_ROOT}/usr/lib/debug | cut -f1)
-    $quiet || echo "original debug info size: ${size_before}kB, size after compression: ${size_after}kB"
+    $verbose && size_after=$(du -sk ${RPM_BUILD_ROOT}/usr/lib/debug | cut -f1)
+    $verbose && echo "original debug info size: ${size_before}kB, size after compression: ${size_after}kB"
     # Remove .dwz directory if empty
     rmdir "${RPM_BUILD_ROOT}/usr/lib/debug/.dwz" 2>/dev/null
 
@@ -625,6 +639,7 @@ fi
 
 # For each symlink whose target has a .debug file,
 # make a .debug symlink to that file.
+$quiet || echo "Creating .debug symlinks for symlinks to ELF files" 2>&1
 find "$RPM_BUILD_ROOT" ! -path "${debugdir}/*" -type l -print |
 while read f
 do
@@ -632,7 +647,7 @@ do
   f=${f#$RPM_BUILD_ROOT}
   t=${t#$RPM_BUILD_ROOT}
   if [ -f "$debugdir$t" ]; then
-    $quiet || echo "symlinked /usr/lib/debug$t to /usr/lib/debug${f}.debug"
+    $verbose && echo "symlinked /usr/lib/debug$t to /usr/lib/debug${f}.debug"
     debug_link "/usr/lib/debug$t" "${f}.debug"
   fi
 done
@@ -646,6 +661,7 @@ if [ -s "$SOURCEFILE" ]; then
     debug_dest_name="/usr/src/debug/${unique_debug_src_base}"
   fi
 
+  $quiet || echo "Copying sources found by 'debugedit -l' to ${debug_dest_name}" 2>&1
   mkdir -p "${RPM_BUILD_ROOT}${debug_dest_name}"
   # Filter out anything compiler generated which isn't a source file.
   # e.g. <internal>, <built-in>, <__thread_local_inner macros>.
@@ -761,3 +777,5 @@ if ((nout > 0)); then
   cat "$LISTFILE" >> "${LISTFILE}.new"
   mv "${LISTFILE}.new" "$LISTFILE"
 fi
+
+$quiet || echo "find-debuginfo: done" 2>&1
-- 
2.40.1

Re: [PATCH] find-debuginfo: unless -q -q, print messages what big steps we are at

[Denys Vlasenko]

On 6/30/23 15:25, Mark Wielaard wrote:
> Hi Denys,
> 
> On Thu, 2023-06-29 at 16:13 +0200, Mark Wielaard wrote:
>>> We can give a few messages explaining what general steps we go through:
>>>
>>>      Extracting debug info from N files
>>>      DWARF-compressing N files
>>>      Creating .debug symlinks for symlinks to ELF files
>>>      Copying sources found by 'debugedit -l'
>>>
>>> This is also useful to get a feeling which steps are time consuming.
>>> Kernel builds often need to investigate this aspect. To help a bit more,
>>> add "find-debuginfo: starting" and "find-debuginfo: done" messages too.
>>>
>>> This patch adds these messages.
>>>
>>> Two -q -q options suppress these messages too.
>>
>> I like this idea, but I am wondering if instead of -q -q we should
>> have a -v,--verbose flag for the very verbose output. Then this
>> explanary output could be the default. And -q,--quiet would suppress
>> even those message.
> 
> So this is what I was thinking. What do you think?
> https://code.wildebeest.org/git/user/mjw/debugedit/commit/?h=verbose

Looks good. We will be able to revert

"Suppress 'extracting debug info' noise in build log"

+%if 0%{?fedora}
+%global _find_debuginfo_opts -r -q
+%else
  %global _find_debuginfo_opts -r
+%endif

change in our kernel specfile (always good to have fewer special cases)
and still have what that change intended: not-very-verbose find-debuginfo output.

Re: [PATCH] find-debuginfo: unless -q -q, print messages what big steps we are at

[Mark Wielaard]

Hi Denys,

On Fri, Jun 30, 2023 at 08:51:35PM +0200, Denys Vlasenko wrote:
> Looks good. We will be able to revert
> 
> "Suppress 'extracting debug info' noise in build log"
> 
> +%if 0%{?fedora}
> +%global _find_debuginfo_opts -r -q
> +%else
>  %global _find_debuginfo_opts -r
> +%endif
> 
> change in our kernel specfile (always good to have fewer special
> cases) and still have what that change intended: not-very-verbose
> find-debuginfo output.

Great. I'll backport to the fedora package too then.

Cheers,

Mark