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
signature.asc
Description: PGP signature