Bug#1012318: diffoscope 214 produced no output and was killed after running into timeout after 150m
Vagrant Cascadian
vagrant at reproducible-builds.org
Tue Jun 7 23:17:12 BST 2022
On 2022-06-06, Chris Lamb wrote:
> Vagrant Cascadian wrote:
> It's not strictly a *bug* that diffoscope takes a long time, but it is
> curious that the best-effort "--timeout" is not kicking in early enough
> and ensuring that the harsher timeout does not kill diffoscope outright.
>
> Indeed, the --timeout option was implemented precisely to avoid having
> no output whatsoever on tests.r-b.org.
Nevertheless, it could get stuck on some arbitrary file, no? Or does it
actually try to abort processing a file if it is taking too long?
> Vagrant, do you have --profile output, out of interest? It would be
> interesting, for instance, if the HTML generation was taking so long
> that even if diffoscope stopped recursing into subarchives, it hit
> Jenkins' hard timeout. This may suggest that there is a bug in the
> HTML generation, and/or that the --timeout value on tests.r-b.org has
> not been set low enough relative to the hard timeout.
Yeah, I think maybe we should add more time to the hard jenkins timeout
to make sure it really gets *some* output.
The original was just the defaults that reprotest uses (perhaps we
should add --profile?).
I re-ran diffoscope with profile output using the same artifacts....
# Profiling output for: /usr/bin/diffoscope --progress --profile --text=halide.diffoscope control/ experiment-1
## close_archive (total time: 0.001s)
0.000s 24 calls diffoscope.comparators.xz.XzContainer
0.000s 22 calls diffoscope.comparators.tar.TarContainer
0.000s 6 calls diffoscope.comparators.deb.DebContainer
0.000s 10 calls diffoscope.comparators.deb.DebTarContainer
## command (total time: 1816.184s)
805.925s 8949 calls readelf
770.865s 2011 calls diff
232.245s 1188 calls objdump
5.085s 36 calls xz
2.002s 198 calls strings
0.026s 2 calls cmp
0.026s 2 calls cmp (external)
0.004s 54 calls cmp (internal)
0.003s 66 calls stat
0.002s 18 calls objcopy
## compare_files (cumulative) (total time: 3904.923s)
922.891s 6 calls abc.DebFile
922.341s 12 calls abc.XzFile
916.800s 6 calls abc.DebDataTarFile
873.202s 18 calls abc.ElfFile
183.319s 68 calls diffoscope.comparators.elf.ElfCodeSection
46.212s 338 calls diffoscope.comparators.elf.ElfSection
29.528s 1047 calls abc.TextFile
10.056s 34 calls diffoscope.comparators.elf.ElfStringSection
0.446s 6 calls abc.TarFile
0.126s 6 calls abc.Md5sumsFile
0.000s 1 call diffoscope.comparators.directory.FilesystemDirectory
## container_extract (total time: 6.318s)
5.089s 36 calls diffoscope.comparators.xz.XzContainer
1.109s 6388 calls diffoscope.comparators.deb.DebTarContainer
0.098s 48 calls diffoscope.comparators.deb.DebContainer
0.022s 40 calls diffoscope.comparators.tar.TarContainer
## has_same_content_as (total time: 0.109s)
0.071s 1057 calls abc.TextFile
0.016s 9 calls abc.DebFile
0.013s 6 calls abc.DebDataTarFile
0.003s 338 calls diffoscope.comparators.elf.ElfSection
0.002s 18 calls abc.ElfFile
0.001s 12 calls abc.Md5sumsFile
0.001s 12 calls abc.XzFile
0.001s 6 calls abc.TarFile
0.001s 68 calls diffoscope.comparators.elf.ElfCodeSection
0.000s 3 calls diffoscope.comparators.utils.libarchive.LibarchiveSymlink
0.000s 34 calls diffoscope.comparators.elf.ElfStringSection
0.000s 1 call diffoscope.comparators.directory.FilesystemDirectory
## main (total time: 935.422s)
935.417s 2 calls outputs
0.005s 1 call cleanup
## open_archive (total time: 0.001s)
0.000s 36 calls diffoscope.comparators.xz.XzContainer
0.000s 24 calls diffoscope.comparators.tar.TarContainer
0.000s 12 calls diffoscope.comparators.deb.DebTarContainer
0.000s 12 calls diffoscope.comparators.deb.DebContainer
## output (total time: 12.131s)
12.131s 1 call text
## recognizes (total time: 8.809s)
7.074s 51970 calls diffoscope.comparators.utils.libarchive.LibarchiveMember
1.111s 7436 calls diffoscope.comparators.elf.ElfSection
0.240s 1496 calls diffoscope.comparators.elf.ElfCodeSection
0.221s 1488 calls diffoscope.comparators.utils.archive.ArchiveMember
0.119s 748 calls diffoscope.comparators.elf.ElfStringSection
0.043s 468 calls diffoscope.comparators.binary.FilesystemFile
0.001s 96 calls abc.Md5sumsFile
0.000s 12 calls diffoscope.comparators.utils.libarchive.LibarchiveSymlink
## specialize (total time: 9.476s)
9.476s 1564 calls specialize
And again for html generation:
# Profiling output for: /usr/bin/diffoscope --progress --profile --html halide.diffoscope.out.html control/ experiment-1
## close_archive (total time: 0.001s)
0.000s 24 calls diffoscope.comparators.tar.TarContainer
0.000s 36 calls diffoscope.comparators.xz.XzContainer
0.000s 12 calls diffoscope.comparators.deb.DebContainer
0.000s 12 calls diffoscope.comparators.deb.DebTarContainer
## command (total time: 1784.837s)
784.955s 8949 calls readelf
757.622s 2011 calls diff
235.317s 1188 calls objdump
4.824s 36 calls xz
2.056s 198 calls strings
0.027s 2 calls cmp
0.027s 2 calls cmp (external)
0.004s 54 calls cmp (internal)
0.003s 66 calls stat
0.002s 18 calls objcopy
## compare_files (cumulative) (total time: 3866.521s)
915.357s 6 calls abc.DebFile
914.809s 12 calls abc.XzFile
909.520s 6 calls abc.DebDataTarFile
856.681s 18 calls abc.ElfFile
184.384s 68 calls diffoscope.comparators.elf.ElfCodeSection
46.102s 338 calls diffoscope.comparators.elf.ElfSection
29.150s 1047 calls abc.TextFile
9.956s 34 calls diffoscope.comparators.elf.ElfStringSection
0.440s 6 calls abc.TarFile
0.123s 6 calls abc.Md5sumsFile
0.001s 1 call diffoscope.comparators.directory.FilesystemDirectory
## container_extract (total time: 6.051s)
4.827s 36 calls diffoscope.comparators.xz.XzContainer
1.104s 6388 calls diffoscope.comparators.deb.DebTarContainer
0.096s 48 calls diffoscope.comparators.deb.DebContainer
0.023s 40 calls diffoscope.comparators.tar.TarContainer
## diff (total time: 15.681s)
15.681s 7207 calls linediff
## has_same_content_as (total time: 0.109s)
0.070s 1057 calls abc.TextFile
0.016s 6 calls abc.DebDataTarFile
0.014s 9 calls abc.DebFile
0.003s 338 calls diffoscope.comparators.elf.ElfSection
0.002s 18 calls abc.ElfFile
0.001s 12 calls abc.Md5sumsFile
0.001s 12 calls abc.XzFile
0.001s 6 calls abc.TarFile
0.001s 68 calls diffoscope.comparators.elf.ElfCodeSection
0.000s 3 calls diffoscope.comparators.utils.libarchive.LibarchiveSymlink
0.000s 34 calls diffoscope.comparators.elf.ElfStringSection
0.000s 1 call diffoscope.comparators.directory.FilesystemDirectory
## main (total time: 1329.326s)
1329.326s 2 calls outputs
0.000s 1 call cleanup
## open_archive (total time: 0.001s)
0.000s 36 calls diffoscope.comparators.xz.XzContainer
0.000s 24 calls diffoscope.comparators.tar.TarContainer
0.000s 12 calls diffoscope.comparators.deb.DebTarContainer
0.000s 12 calls diffoscope.comparators.deb.DebContainer
## output (total time: 413.571s)
413.571s 1 call html
## recognizes (total time: 8.921s)
7.049s 51970 calls diffoscope.comparators.utils.libarchive.LibarchiveMember
1.216s 7436 calls diffoscope.comparators.elf.ElfSection
0.255s 1496 calls diffoscope.comparators.elf.ElfCodeSection
0.224s 1488 calls diffoscope.comparators.utils.archive.ArchiveMember
0.128s 748 calls diffoscope.comparators.elf.ElfStringSection
0.047s 468 calls diffoscope.comparators.binary.FilesystemFile
0.001s 96 calls abc.Md5sumsFile
0.000s 12 calls diffoscope.comparators.utils.libarchive.LibarchiveSymlink
## specialize (total time: 9.574s)
9.574s 1564 calls specialize
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 227 bytes
Desc: not available
URL: <http://alioth-lists.debian.net/pipermail/reproducible-builds/attachments/20220607/7ad0901e/attachment.sig>
More information about the Reproducible-builds
mailing list