Bugzilla – Bug 1097006
dwz debuginfo splitting is one-thread and very very slow on packages which have too many libs
Last modified: 2021-03-10 10:23:02 UTC
Obs generates dwz compression for all items at once to reduce space: [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/auth_0x0100.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/adt_null.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/auth_ed25519.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/auth_gssapi.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/auth_pam.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/auth_socket.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/disks.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/client_ed25519.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/dialog_examples.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/auth_test_plugin.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_blackhole.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/file_key_management.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/example_key_management.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_connect.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_archive.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_example.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_federated.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_mroonga.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_oqgraph.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_federatedx.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_rocksdb.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_sphinx.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_spider.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/handlersocket.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/libdaemon_example.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/locales.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/ha_test_sql_discovery.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/metadata_lock_info.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/qa_auth_client.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/query_cache_info.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/mypluglib.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/qa_auth_interface.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/qa_auth_server.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/query_response_time.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/semisync_slave.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/sql_errlog.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/semisync_master.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/server_audit.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/sbin/mysqld [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/simple_password_check.so [ 209s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/wsrep_info.so [ 497s] /usr/lib/rpm/sepdebugcrcfix: Updated 80 CRC32s, 0 CRC32s did match. As you can see whole build took 209s while dwz split another 288s utilizing just one core. The -multifile mode tries to reduce the size even more, but question is if there are enough gains to justify the slowdown.
Can you Tomas please attach some numbers how big is debug info w/ and w/o dwz?
[ 98s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/lib64/mysql/plugin/simple_password_check.so [ 384s] /usr/lib/rpm/sepdebugcrcfix: Updated 80 CRC32s, 0 CRC32s did match. tchvatal@kunlun: /dev/shm/tchvatal/tmp/build-root/openSUSE_Tumbleweed-x86_64/home/abuild/rpmbuild/RPMS/x86_64 $ ls -laF *debuginfo* -rw-r--r-- 1 399 399 18M 12. čen 10.21 libmysqld19-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 511K 12. čen 10.21 mariadb-bench-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 1,6M 12. čen 10.21 mariadb-client-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 109M 12. čen 10.20 mariadb-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 37M 12. čen 10.22 mariadb-test-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 19M 12. čen 10.22 mariadb-tools-debuginfo-10.2.15-0.x86_64.rpm [ 98s] extracting debug info from /home/abuild/rpmbuild/BUILDROOT/mariadb-10.2.15-0.x86_64/usr/sbin/mysqld [ 105s] cpio: build/storage/include/fts0blex.h: Cannot stat: No such file or directory tchvatal@kunlun: /dev/shm/tchvatal/tmp/build-root/openSUSE_Tumbleweed-x86_64/home/abuild/rpmbuild/RPMS/x86_64 $ ls -laF *debuginfo* -rw-r--r-- 1 399 399 28M 12. čen 10.43 libmysqld19-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 721K 12. čen 10.43 mariadb-bench-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 2,1M 12. čen 10.43 mariadb-client-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 139M 12. čen 10.42 mariadb-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 58M 12. čen 10.44 mariadb-test-debuginfo-10.2.15-0.x86_64.rpm -rw-r--r-- 1 399 399 29M 12. čen 10.45 mariadb-tools-debuginfo-10.2.15-0.x86_64.rpm
DWZ is limited by some params but indeed it is single-threaded. I'm not sure how much of it could be done in parallel (I suspect nothing without a significant rewrite). Do we really care so much about the build time? I ask because debuginfo extraction (esp. debugedit) is consuming a big amount of time as well. Note in single-file mode the dwz invocations could be done in parallel (likewise the debug info extraction). That would be rpms (find-debuginfo.sh) job.
(In reply to Richard Biener from comment #3) > DWZ is limited by some params but indeed it is single-threaded. I'm not > sure how much of it could be done in parallel (I suspect nothing without a > significant rewrite). Do we really care so much about the build time? I > ask because > debuginfo extraction (esp. debugedit) is consuming a big amount of time as > well. > Note in single-file mode the dwz invocations could be done in parallel > (likewise > the debug info extraction). That would be rpms (find-debuginfo.sh) job. It is slowing all the staging projects/etc. Which we rebuild daily. If we take look only on stock SLE rebuild counter we rebuild everything quite significantly http://ostrich.suse.de/build-times/project/SUSE:SLE-15:GA/index.html thus if we spent 3 mins on avg doing something it is unfortunate. Maybe we should disable dwz on staging projects to speed up at least those common rebuilds. FWIW there are even bigger slowdowns in lieu of brp checks and rpmlint but the plan is to look at them somehow too.
I will look into this but I won't do any major changes unless that code comes from upstream.
(In reply to Philipp Thomas from comment #5) > I will look into this but I won't do any major changes unless that code > comes from upstream. I wouldn't close it as wontfix. We now have a new team member (Tom) and dwz is definitely one thing he can potentially work on. Thus re-opening.
(In reply to Richard Biener from comment #3) > DWZ is limited by some params but indeed it is single-threaded. I'm not > sure how much of it could be done in parallel (I suspect nothing without a > significant rewrite). Do we really care so much about the build time? I > ask because > debuginfo extraction (esp. debugedit) is consuming a big amount of time as > well. That's currently being rewritten, so it should speed up soon. > Note in single-file mode the dwz invocations could be done in parallel > (likewise > the debug info extraction). That would be rpms (find-debuginfo.sh) job. But if I'm correct, most benefits are achieved when run on all binaries, right?
(In reply to Martin Liška from comment #7) > (In reply to Richard Biener from comment #3) > > DWZ is limited by some params but indeed it is single-threaded. I'm not > > sure how much of it could be done in parallel (I suspect nothing without a > > significant rewrite). Do we really care so much about the build time? I > > ask because > > debuginfo extraction (esp. debugedit) is consuming a big amount of time as > > well. > > That's currently being rewritten, so it should speed up soon. > > > Note in single-file mode the dwz invocations could be done in parallel > > (likewise > > the debug info extraction). That would be rpms (find-debuginfo.sh) job. > > But if I'm correct, most benefits are achieved when run on all binaries, > right? Yes.
There are some statistics that I took on a staging project. It presents how much time is spent in package builds with dwz tool: Top 50 by time: mozjs52.log 778 / 2381s 32.68% mariadb.log 371 / 4096s 9.06% kernel-vanilla.log 166 / 515s 32.23% kernel-debug.log 157 / 519s 30.25% python-qt5.log 153 / 2010s 7.61% qemu.log 129 / 1401s 9.21% gcc8.log 119 / 5980s 1.99% gcc7.log 89 / 4481s 1.99% libreoffice.log 76 / 28738s 0.26% plasma5-desktop.log 75 / 1308s 5.73% kopete.log 63 / 1201s 5.25% wireshark.log 59 / 1676s 3.52% amarok.log 56 / 675s 8.30% kdepim-runtime.log 54 / 1216s 4.44% kwin5.log 53 / 599s 8.85% opencv.log 48 / 1275s 3.76% kdepim-addons.log 46 / 712s 6.46% libqt5-qtquickcontrols2.log 33 / 389s 8.48% libstorage-ng.log 32 / 1255s 2.55% openblas:openmp.log 32 / 2086s 1.53% akonadi-server.log 30 / 559s 5.37% intel-gpu-tools.log 30 / 389s 7.71% libmwaw.log 28 / 529s 5.29% Mesa-demo.log 28 / 280s 10.00% messagelib.log 27 / 391s 6.91% pcp.log 27 / 1555s 1.74% vlc.log 26 / 711s 3.66% openblas:serial.log 26 / 1601s 1.62% libzypp.log 25 / 948s 2.64% kleopatra.log 25 / 477s 5.24% openblas:pthreads.log 25 / 1764s 1.42% okular.log 25 / 329s 7.60% kmail.log 23 / 335s 6.87% libetonyek.log 22 / 270s 8.15% kate.log 20 / 314s 6.37% highlight.log 19 / 202s 9.41% plasma5-addons.log 18 / 365s 4.93% texlive.log 17 / 2286s 0.74% mailcommon.log 17 / 383s 4.44% plasma-nm5.log 17 / 310s 5.48% korganizer.log 16 / 266s 6.02% kmail-account-wizard.log 16 / 188s 8.51% kdebase4-runtime.log 16 / 326s 4.91% systemtap.log 16 / 347s 4.61% dolphin.log 16 / 249s 6.43% xorg-x11-server.log 15 / 371s 4.04% ekiga.log 15 / 364s 4.12% gwenview5.log 15 / 222s 6.76% btrfsprogs.log 14 / 140s 10.00% opal.log 14 / 312s 4.49% Top 50 by percentage of package build time: mozjs52.log 778 / 2381s 32.68% kernel-vanilla.log 166 / 515s 32.23% kernel-debug.log 157 / 519s 30.25% btrfsprogs.log 14 / 140s 10.00% Mesa-demo.log 28 / 280s 10.00% highlight.log 19 / 202s 9.41% qemu.log 129 / 1401s 9.21% mariadb.log 371 / 4096s 9.06% kwin5.log 53 / 599s 8.85% kmail-account-wizard.log 16 / 188s 8.51% libqt5-qtquickcontrols2.log 33 / 389s 8.48% amarok.log 56 / 675s 8.30% libetonyek.log 22 / 270s 8.15% intel-gpu-tools.log 30 / 389s 7.71% python-qt5.log 153 / 2010s 7.61% okular.log 25 / 329s 7.60% signon-ui.log 9 / 122s 7.38% virtualbox.log 14 / 200s 7.00% messagelib.log 27 / 391s 6.91% kmail.log 23 / 335s 6.87% gwenview5.log 15 / 222s 6.76% kdepim-addons.log 46 / 712s 6.46% dolphin.log 16 / 249s 6.43% kate.log 20 / 314s 6.37% korganizer.log 16 / 266s 6.02% sddm.log 8 / 134s 5.97% libqt5-qtquickcontrols.log 12 / 202s 5.94% kdiagram.log 11 / 190s 5.79% plasma5-desktop.log 75 / 1308s 5.73% libkgapi.log 12 / 218s 5.50% plasma-nm5.log 17 / 310s 5.48% zypper.log 11 / 203s 5.42% akonadi-server.log 30 / 559s 5.37% libmwaw.log 28 / 529s 5.29% kopete.log 63 / 1201s 5.25% kleopatra.log 25 / 477s 5.24% knotes.log 10 / 197s 5.08% libksieve.log 12 / 236s 5.08% plasma5-addons.log 18 / 365s 4.93% kdebase4-runtime.log 16 / 326s 4.91% xscreensaver.log 12 / 254s 4.72% powerdevil5.log 8 / 170s 4.71% systemtap.log 16 / 347s 4.61% konsole.log 11 / 244s 4.51% opal.log 14 / 312s 4.49% akregator.log 10 / 223s 4.48% kdepim-runtime.log 54 / 1216s 4.44% mailcommon.log 17 / 383s 4.44% ekiga.log 15 / 364s 4.12% discover.log 7 / 173s 4.05% Total time: 4198s (1.66 %) of 979 packages (of 2487), average: 4.29s, total package build time: 253515s
See also upstream PR25951 - support for parallel processing ( https://sourceware.org/bugzilla/show_bug.cgi?id=25951 ).