User:Vazhnov/Dirty hacks

From Gentoo Wiki
Jump to:navigation Jump to:search
Warning
Information below are dirty workarounds!

Maybe it will help to anybody who wants to do some digging.

Add GNU time to emerge

The problem

When I tried to emerge Firefox, I've received system hang because of out of memory: User:Vazhnov/Knowledge Base:emerge out of memory. My swap made a lot of writes and reduced SSD lifetime.

I want to see "Maximum resident set size" for ebuild compile, to get some memory usage info for problem User:Vazhnov/Knowledge Base:emerge out of memory. I use "/usr/bin/time -v" (GNU time) for this.

How compile process looks: 

 $ ps -eF --forest
…
root     30385 25074 27 37937 144860  0 19:39 pts/4    00:00:12  |           \_ /usr/bin/python3.6 -b /usr/lib/python-exec/python3.6/emerge -n gnome-extra/gnome-calculator
root      1776 30385  0  3928  9696   1 19:40 pts/4    00:00:00  |               \_ /usr/bin/python3.6m /usr/lib/portage/python3.6/pid-ns-init 1777
root      1777  1776  0  3928  9784   4 19:40 pts/6    00:00:00  |                   \_ /usr/bin/python3.6m /usr/lib/portage/python3.6/pid-ns-init 250 250 250 18 0,1,2 /usr/bi
portage   1780  1777  0   593  1692   5 19:40 pts/6    00:00:00  |                       \_ [x11-libs/gtksourceview-4.2.0] sandbox /usr/lib/portage/python3.6/ebuild.sh compile
portage   1781  1780  0  3217  7612   3 19:40 pts/6    00:00:00  |                           \_ /bin/bash /usr/lib/portage/python3.6/ebuild.sh compile
portage   1803  1781  0  3219  6728   2 19:40 pts/6    00:00:00  |                               \_ /bin/bash /usr/lib/portage/python3.6/ebuild.sh compile
portage   1808  1803  0  2395  4112   0 19:40 pts/6    00:00:00  |                                   \_ /bin/bash /usr/lib/portage/python3.6/ebuild-helpers/emake
portage   1810  1808  0  1972  2684   1 19:40 pts/6    00:00:00  |                                       \_ make -j6
portage   1813  1810  0  1970  2724   4 19:40 pts/6    00:00:00  |                                           \_ make all-recursive

/usr/bin/time example output

  • Command was: /usr/bin/time -v sudo emerge -n virtual/rust
  • MAKEOPTS="-j4" in /etc/portage/make.conf
  • 4GB RAM is not enough for this, so swap was used:
 $ free -m
              total        used        free      shared  buff/cache   available
Mem:           3840        3484          55          20         300         278
Swap:          4999         759        4240
 $ ps -eF --forest
…
lenin     6853     1  0  2864  1516   1 15:56 ?        00:00:04 tmux
lenin     6854  6853  0  2703  1708   1 15:56 pts/1    00:00:00  \_ -zsh
lenin     6859  6854  0   562    60   0 15:56 pts/1    00:00:00      \_ /usr/bin/time -v sudo emerge -n virtual/rust
root      6860  6859  0  2148   536   1 15:56 pts/1    00:00:00          \_ sudo emerge -n virtual/rust
root      6861  6860  0 25128 65568   1 15:56 pts/1    00:00:24              \_ /usr/bin/python3.7 -b /usr/lib/python-exec/python3.7/emerge -n virtual/rust
root     18393  6861  0  3843  1092   1 15:59 pts/1    00:00:00                  \_ /usr/bin/python3.7m /usr/lib/portage/python3.7/pid-ns-init 18394
root     18394 18393  0  3844  1236   0 15:59 pts/2    00:00:00                      \_ /usr/bin/python3.7m /usr/lib/portage/python3.7/pid-ns-init 250 250 250 18 0,1,2 
portage  18397 18394  0   572   456   3 15:59 pts/2    00:00:00                          \_ [dev-lang/rust-1.41.1] sandbox /usr/lib/portage/python3.7/ebuild.sh compile
portage  18398 18397  0  3264   492   3 15:59 pts/2    00:00:00                              \_ /bin/bash /usr/lib/portage/python3.7/ebuild.sh compile
portage  18414 18398  0  3263   448   0 15:59 pts/2    00:00:00                                  \_ /bin/bash /usr/lib/portage/python3.7/ebuild.sh compile
portage  18424 18414  0  5274   848   2 15:59 pts/2    00:00:00                                      \_ python3.6 ./x.py build -vv --config=/var/tmp/notmpfs/portage/dev
portage  19486 18424  0  5215  7456   1 16:00 pts/2    00:00:01                                          \_ /var/tmp/notmpfs/portage/dev-lang/rust-1.41.1/work/rustc-1.4
portage   3114 19486  0 176938 28556  1 17:42 pts/2    00:00:04                                              \_ /var/tmp/notmpfs/portage/dev-lang/rust-1.41.1/work/rust-
portage   6273  3114 86 691472 1777400 1 17:46 pts/2   00:15:34                                                  \_ /var/tmp/notmpfs/portage/dev-lang/rust-1.41.1/work/r
portage   6678  3114 95 427741 1207816 3 17:56 pts/2   00:07:43                                                  \_ /var/tmp/notmpfs/portage/dev-lang/rust-1.41.1/work/r
portage   6914  3114 98 166234 349452 3 18:02 pts/2    00:02:17                                                  \_ /var/tmp/notmpfs/portage/dev-lang/rust-1.41.1/work/r
portage   7017  3114 12 58113 56464   1 18:04 pts/2    00:00:00                                                  \_ /var/tmp/notmpfs/portage/dev-lang/rust-1.41.1/work/r

The output is: 

        Command being timed: "sudo emerge -n virtual/rust"
        User time (seconds): 38526.59
        System time (seconds): 824.97
        Percent of CPU this job got: 368%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 2:58:05
        Average shared text size (kbytes): 0
        Average unshared data size (kbytes): 0
        Average stack size (kbytes): 0
        Average total size (kbytes): 0
        Maximum resident set size (kbytes): 2246920
        Average resident set size (kbytes): 0
        Major (requiring I/O) page faults: 106085
        Minor (reclaiming a frame) page faults: 157744830
        Voluntary context switches: 2173051
        Involuntary context switches: 1865943
        Swaps: 0
        File system inputs: 7552472
        File system outputs: 22477776
        Socket messages sent: 0
        Socket messages received: 0
        Signals delivered: 0
        Page size (bytes): 4096
        Exit status: 0

Iteration one: /usr/bin/ebuild

First I tried to replace /usr/bin/ebuild which is symlink to /usr/lib/python-exec/python-exec2.

I can't replace original /usr/lib/python-exec/python-exec2 and call it from bash wrapper because of error:

/usr/lib/python-exec/python-exec2: python-exec2 is a wrapper, it must not be run directly.

It needs to be pointed by symlink, but not by bash script wrapper.

I did it successfully by:

FILE /usr/lib/python-exec/python-exec2-time
#!/bin/sh
echo "### ebuild GNU time started at $(date --iso-8601=seconds)" >> /var/log/emerge-time.log
/usr/bin/time --verbose --append --output=/var/log/emerge-time.log -- /usr/lib/python-exec/python3.6/ebuild "$@"
echo "### ebuild GNU time finished at $(date --iso-8601=seconds)" >> /var/log/emerge-time.log
root #ln -b -s "../lib/python-exec/python-exec2-time" /usr/bin/ebuild

But then I realized that emerge not uses /usr/bin/ebuild.

Fail!

emerge uses some python code to run /usr/lib/portage/python3.6/ebuild.sh:

FILE /usr/lib64/python3.6/site-packages/portage/package/ebuild/doebuild.py
def doebuild(myebuild, mydo, _unused=DeprecationWarning, settings=None, debug=0, listonly=0,
	fetchonly=0, cleanup=0, dbkey=DeprecationWarning, use_cache=1, fetchall=0, tree=None,
	mydbapi=None, vartree=None, prev_mtimes=None,
	fd_pipes=None, returnpid=False):
	"""
	Wrapper function that invokes specific ebuild phases through the spawning
	of ebuild.sh
FILE /usr/lib64/python3.6/site-packages/portage/const.py
EBUILD_SH_BINARY         = PORTAGE_BIN_PATH + "/ebuild.sh"

Iteration two: /usr/lib/portage/python3.7/ebuild.sh

Save original file:

root #mv /usr/lib/portage/python3.7/ebuild.sh /usr/lib/portage/python3.7/ebuild.sh.ORIG

Create file:

FILE /usr/lib/portage/python3.7/ebuild.sh
#!/bin/bash
if [ "$1" == "compile" ]; then
  /usr/bin/time --verbose -- /usr/lib/portage/python3.7/ebuild.sh.ORIG "$@"
  echo -n "Disk usage (du -sx -BM): "
  du -sx -BM "$PORTAGE_BUILDDIR"
else
  source /usr/lib/portage/python3.7/ebuild.sh.ORIG
fi

Set permissions:

root #chmod +x /usr/lib/portage/python3.7/ebuild.sh

I tried to save information I need to /var/log/, but unfortunately it is sandboxed (I had to add rules into /etc/sandbox.d/): 

 * ACCESS DENIED:  open_wr:      /var/log/emerge-time.log
/usr/lib/portage/python3.6/ebuild.sh: line 8: /var/log/emerge-time.log: Permission denied
 * ACCESS DENIED:  fopen_wr:     /var/log/emerge-time.log
/usr/bin/time: /var/log/emerge-time.log: Permission denied
 * ACCESS DENIED:  open_wr:      /var/log/emerge-time.log
/usr/lib/portage/python3.6/ebuild.sh: line 10: /var/log/emerge-time.log: Permission denied
 * --------------------------- ACCESS VIOLATION SUMMARY ---------------------------
 * LOG FILE: "/var/tmp/portage/gnome-extra/gnome-calculator-3.32.2/temp/sandbox.log"

So I can write into /tmp/.

Then I found PORTAGE_LOGDIR allows to save build logs, with all STDOUT and STDERR output of ebuild.sh.

Result

Final output example /var/log/portage/gnome-extra:gnome-calculator-3.32.2:20200418-214802.log: 

>>> Compiling source in /var/tmp/portage/gnome-extra/gnome-calculator-3.32.2/work/gnome-calculator-3.32.2 ...
ninja -v -j6 -l0 -C /var/tmp/portage/gnome-extra/gnome-calculator-3.32.2/work/gnome-calculator-3.32.2-build
…
>>> Source compiled.
	Command being timed: "/usr/lib/portage/python3.6/ebuild.sh.ORIG compile"
	User time (seconds): 29.38
	System time (seconds): 2.63
	Percent of CPU this job got: 403%
	Elapsed (wall clock) time (h:mm:ss or m:ss): 0:07.93
	Average shared text size (kbytes): 0
	Average unshared data size (kbytes): 0
	Average stack size (kbytes): 0
	Average total size (kbytes): 0
	Maximum resident set size (kbytes): 145368
	Average resident set size (kbytes): 0
	Major (requiring I/O) page faults: 0
	Minor (reclaiming a frame) page faults: 735962
	Voluntary context switches: 2626
	Involuntary context switches: 9964
	Swaps: 0
	File system inputs: 0
	File system outputs: 20312
	Socket messages sent: 0
	Socket messages received: 0
	Signals delivered: 0
	Page size (bytes): 4096
	Exit status: 0

Create mediawiki table

FILE ./Gentoo_portage_parse_timelogs_to_mediawiki.sh
#!/usr/bin/env bash
set -o nounset
set -o pipefail
shopt -s dotglob

# Usage example:
# ./Gentoo_portage_parse_timelogs_to_mediawiki.sh

echo '{| border="1" class="wikitable sortable"'
echo "! Package name !! Jobs !! Maximum resident set size (kbytes) !! Disk usage !! Elapsed (wall clock) time (h:mm:ss or m:ss) !! CPU !! Exit code"

for logfile in /var/log/portage/*.log; do
  # Only for log with `/usr/bin/time --verbose` output:
  if grep -q 'Command being timed: ' "$logfile"; then
    PACKAGE=$(grep '^ \* Package:' "$logfile" | tr -s '[:blank:]' | cut -d ':' -s -f 2-)
    # tr '\n' ' ' — is for dev-libs/openssl, it has two lines with -jX
    JOBS=$(grep -A12 '^>>> Compiling source in' "$logfile" | grep --max-count=1 --only-matching ' -j[[:digit:]]' | tr '\n' ' ')
    MAXRES=$(grep 'Maximum resident set size (kbytes):' "$logfile" | grep --max-count=1 --only-matching '[[:digit:]]\+')
    # Don't take milliseconds (after dot) to do simple sort in table
    WALLTIME=$(grep 'Elapsed (wall clock) time (h:mm:ss or m:ss):' "$logfile" | grep --max-count=1 --only-matching '[[:digit:]]\+:[[:digit:]]\+:*[[:digit:]]*')
    CPU=$(grep 'Percent of CPU this job got:' "$logfile" | grep --max-count=1 --only-matching '[[:digit:]]*\%')
    DISK=$(grep '^Disk usage (du -s' "$logfile" | grep --max-count=1 --only-matching '[[:digit:]]\+[KMGTPEZY]')
    EXIT=$(grep 'Exit status:' "$logfile" | grep --max-count=1 --only-matching '[[:digit:]]\+')
    echo "|-"
    echo "| $PACKAGE	|| $JOBS	|| align=\"right\" | $MAXRES	|| $DISK	|| align=\"right\" | $WALLTIME	|| align=\"right\" | $CPU	|| align=\"center\" | $EXIT"
  fi
done
echo '|}'

Table

Package name Jobs Maximum resident set size (kbytes) Disk usage Elapsed (wall clock) time (h:mm:ss or m:ss) CPU Exit code
app-accessibility/at-spi2-atk-2.34.2 -j6 42800 0:03 438% 0
app-accessibility/at-spi2-core-2.34.0 -j6 47640 0:05 309% 0
app-crypt/libsecret-0.20.2 -j6 68220 0:08 342% 0
app-eselect/eselect-java-0.4.0 -j6 19668 0:00 114% 0
app-misc/workrave-1.10.20 -j6 322312 0:48 359% 0
app-portage/gentoolkit-0.4.8 19736 0:00 107% 0
app-text/evince-3.34.2 -j6 146404 0:58 325% 0
dev-cpp/glibmm-2.62.0 -j6 233520 1:13 513% 0
dev-cpp/pangomm-2.42.1 -j6 158184 0:10 436% 0
dev-java/icedtea-bin-3.15.0 19596 0:00 108% 0
dev-java/icedtea-sound-1.0.1 -j6 116992 0:07 261% 0
dev-java/java-config-2.2.0-r4 19880 0:00 88% 0
dev-lang/python-3.8.2-r1 -j6 173040 0:40 434% 0
dev-lang/vala-0.46.7 -j6 162240 0:40 442% 0
dev-libs/angelscript-2.34.0 -j6 164676 0:13 329% 0
dev-libs/atk-2.34.1 -j6 45040 0:05 230% 0
dev-libs/fribidi-1.0.9 -j6 34976 0:02 244% 0
dev-libs/glib-2.62.6 -j6 74388 0:27 559% 0
dev-libs/gobject-introspection-1.62.0 -j6 171912 0:38 243% 0
dev-libs/gobject-introspection-common-1.62.0 19732 0:00 108% 0
dev-libs/libbytesize-2.2 -j6 35052 0:02 134% 0
dev-libs/libgdata-0.17.12 -j6 75064 0:18 392% 0
dev-libs/libgee-0.20.3 -j6 92280 0:12 414% 0
dev-libs/libgweather-3.34.0 -j6 88392 0:07 228% 0
dev-libs/libpcre2-10.34 -j6 201488 0:16 431% 0
dev-libs/libpeas-1.26.0 -j6 87840 0:10 340% 0
dev-libs/openssl-1.1.1g -j6 -j1 73908 0:34 561% 0
dev-libs/vala-common-0.46.7 19712 0:00 108% 0
dev-python/certifi-2019.11.28 24412 0:01 104% 0
dev-python/cheetah-2.4.4-r1 35280 0:03 42% 0
dev-python/markdown-3.1.1-r1 24132 0:01 105% 0
dev-python/pygobject-3.34.0 -j6 64256 0:03 440% 0
dev-python/setuptools-44.0.0 26436 0:06 37% 0
dev-util/gdbus-codegen-2.62.6 45468 0:00 98% 0
dev-util/glib-utils-2.62.6 43940 0:01 80% 0
dev-util/gtk-doc-am-1.32 19892 0:00 108% 0
dev-util/re2c-1.3-r1 -j6 124536 0:13 493% 0
games-action/supertuxkart-1.1 -j6 445128 4:32 563% 0
gnome-base/dconf-0.34.0 -j6 58640 0:04 469% 0
gnome-base/gnome-desktop-3.34.5 -j6 87316 0:06 224% 0
gnome-base/gnome-keyring-3.34.0 -j6 68756 0:37 514% 0
gnome-base/gsettings-desktop-schemas-3.34.0 -j6 29824 0:00 134% 0
gnome-base/gvfs-1.42.2 -j6 81808 0:12 553% 0
gnome-extra/evolution-data-server-3.34.4 -j6 122144 1:43 541% 0
gnome-extra/gnome-calculator-3.34.1 -j6 146348 0:12 458% 0
gnome-extra/yelp-xsl-3.34.2 -j6 19816 0:00 108% 0
mail-client/evolution-3.34.4-r1 -j3 209260 7:52 283% 0
media-gfx/graphicsmagick-1.3.35 -j6 118036 0:28 533% 0
media-libs/clutter-1.26.4 -j6 122592 0:46 410% 0
media-libs/cogl-1.22.6 -j6 68000 0:22 383% 0
net-libs/glib-networking-2.62.3 -j6 57152 0:02 358% 0
net-libs/gnome-online-accounts-3.34.1 -j6 127208 0:28 299% 0
net-libs/libsoup-2.70.0 -j6 65400 0:10 365% 0
sci-geosciences/geocode-glib-3.26.2 -j6 60848 0:04 172% 0
sys-apps/baselayout-java-0.1.0-r1 -j6 19856 0:00 108% 0
sys-apps/bubblewrap-0.3.1-r2 -j6 49040 0:01 159% 0
sys-apps/debianutils-4.9.1 -j6 31072 0:00 111% 0
sys-apps/portage-2.3.89-r3 35320 0:02 82% 0
sys-fs/lvm2-2.02.187-r1 -j6 80168 0:18 448% 0
sys-kernel/genkernel-4.0.7-r1 19928 0:00 108% 0
sys-kernel/installkernel-gentoo-2 19904 0:00 109% 0
sys-libs/libblockdev-2.23-r1 -j6 82756 0:12 284% 0
sys-power/upower-0.99.11 -j6 60792 0:11 240% 0
virtual/jdk-1.8.0-r4 19856 0:00 108% 0
virtual/jpeg-compat-62 19820 0:00 108% 0
virtual/jre-1.8.0-r2 19716 0:00 108% 0
x11-libs/gtksourceview-4.4.0 -j6 94004 0:18 411% 0
x11-libs/vte-0.58.3 -j6 243624 0:16 393% 0
xfce-extra/xfce4-power-manager-1.6.6 -j6 80952 0:09 269% 0
xfce-extra/xfce4-weather-plugin-0.10.1 -j6 84408 0:04 310% 0
app-arch/zip-3.0-r3 -j4 59556 0:04 351% 0
app-crypt/gnupg-2.2.20 -j4 85472 1:00 354% 0
app-emulation/virtualbox-5.2.40 -j4 872544 34:22 397% 1
app-emulation/virtualbox-5.2.40 -j4 873028 34:20 395% 0
app-emulation/virtualbox-modules-5.2.40 -j4 106588 0:30 296% 0
app-eselect/eselect-mpg123-0.1 18008 16K 0:00 108% 0
app-i18n/enca-1.19-r2 -j4 35136 8M 0:04 245% 0
dev-lang/yasm-1.3.0 -j4 59140 0:12 330% 0
dev-libs/libburn-1.5.2_p1 -j4 76864 0:09 295% 0
dev-libs/libIDL-0.8.14-r2 -j4 57852 0:03 218% 0
dev-libs/libisoburn-1.5.2 -j4 60436 0:13 376% 0
dev-libs/libisofs-1.5.2 -j4 65680 0:08 362% 0
dev-libs/nss-3.51 -j4 -j1 81744 3:12 102% 0
dev-qt/qtopengl-5.14.1-r1 -j4 425236 0:44 374% 0
dev-qt/qtprintsupport-5.14.1-r1 -j4 308960 0:31 363% 0
dev-qt/qtx11extras-5.14.1 -j4 199720 0:04 93% 0
dev-util/cbindgen-0.13.2 510672 5:22 351% 0
dev-util/kbuild-0.1.9998.3149 -j4 217068 1:32 257% 0
dev-util/valgrind-3.15.0 -j4 369720 5:02 378% 0
media-fonts/urw-fonts-2.4.9 18000 0:00 107% 0
media-gfx/graphicsmagick-1.3.35 -j4 118164 1:04 388% 0
media-libs/a52dec-0.7.4-r7 -j4 39980 2M 0:02 192% 0
media-libs/audiofile-0.3.6-r3 -j4 89868 0:16 328% 0
media-libs/dav1d-0.5.2 -j4 100648 0:44 362% 0
media-libs/exiftool-11.93 -j4 18044 0:02 107% 0
media-libs/libaom-1.0.0-r2 -j4 292908 2:05 370% 0
media-libs/libass-0.14.0 -j4 59796 7M 0:06 314% 0
media-libs/libdvdcss-1.4.2 -j4 35448 8M 0:01 181% 0
media-libs/libdvdnav-6.0.0 -j4 34580 1M 0:03 231% 0
media-libs/libdvdread-6.0.0 -j4 50792 3M 0:04 203% 0
media-libs/libmad-0.15.1b-r9 -j4 50944 5M 0:02 208% 0
media-libs/libsdl-1.2.15-r9 -j4 58188 0:11 368% 0
media-libs/libtheora-1.1.1-r2 -j4 50696 12M 0:07 325% 0
media-libs/libvpx-1.7.0-r1 -j4 161984 0:59 365% 0
media-sound/mpg123-1.25.10-r1 -j4 51320 4M 0:11 375% 0
media-video/mplayer-1.3.0-r6 -j4 71228 54M 0:41 383% 0
net-dns/c-ares-1.15.0 -j4 38120 0:05 344% 0
net-libs/nghttp2-1.40.0 -j4 57288 0:04 262% 0
net-libs/nodejs-12.16.1 -j4 1061212 46:53 387% 0
sys-auth/nss-mdns-0.14.1 -j4 29136 0:04 302% 0
sys-devel/bin86-0.16.21 -j4 35528 0:03 263% 0
sys-devel/clang-9.0.1 -j4 1772076 1:55:19 391% 0
sys-devel/clang-common-9.0.1 17836 0:00 106% 0
sys-devel/clang-runtime-9.0.1 17904 0:00 108% 0
sys-libs/compiler-rt-9.0.1 -j4 77452 0:15 382% 0
sys-libs/compiler-rt-sanitizers-9.0.1 -j4 173372 3:50 397% 0
sys-libs/libomp-9.0.1 -j4 92960 0:15 368% 0
sys-power/iasl-20200326 -j4 70748 1:02 384% 0
virtual/linux-sources-3-r4 18048 0:00 110% 0
www-client/firefox-68.8.0 -j2 2219596 2:21:15 200% 0
Retrieved from "https://wiki.gentoo.org/index.php?title=User:Vazhnov/Dirty_hacks&oldid=871490"