User:Vazhnov/Dirty hacks

From Gentoo Wiki
Jump to:navigation Jump to:search
Note
Even though this page is in the user namespace, corrections and additions are much appreciated! This is simply wiki policy, this page can be moved to the main wiki as soon as it achieves critical mass more.
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=1040571"