Ceph

Watchig this happen, I observed all 3 osds on a host at 100% CPU, and very very slow progression of log messages through FileStore.

Sadly, valgrind doesn't let you connect to the process w/ gdb while it's running, so i really can't tell what it was doing.. :/

hmm, it is reading the debuginfo file...

lr-x------. 1 root root 64 Mar  2 00:20 12 -> /usr/lib/debug/.dwz/ceph-12.0.0-932.g8d6fb1d.el7.x86_64

pread(12, "\232\230\5\1\324\231\5\2\321\234\5\0<=%-\2\270\3 \1\251\230\5\256\230\5\1\324\231\5\0"..., 8192, 23207936) = 8192
pread(12, "\1\304\2\316\2K\255!\36\274!\36\260!\0(\316\tX\2\264l\1\1\333\2\347\2K\255!9"..., 8192, 23216128) = 8192
pread(12, "2\252\33\0%\201\4T\2\246\20\1js\3\247\33\"\24\0\0\0\0003\32j\2\0\246\21\1\336"..., 8192, 23224320) = 8192
pread(12, "\0\0@\3537-\2\264\247\375\326A\2\221\27\245\31\256\31E\254A6\311\10\0\0\0T\0058-"..., 8192, 23232512) = 8192
pread(12, "\214\1.\1?\31\3\16:\5;\v<\31c\31d\22\1\22\0\0\215\1.\1?\31\3\16:\v"..., 8192, 118603776) = 8192
pread(12, "\23\2\231 *d \0\36\373\232Y\2au\302Y\2$\301p\0\0Gle\10\1\1#^\5"..., 8192, 23248896) = 8192
pread(12, "o\0\0\0\27S\0\"\2\325\27\4\0\5\36\35\365U\2\0b\36k*\1 \237\5n\2\257d"..., 8192, 23265280) = 8192
pread(12, "\31\3\10:\v;\vn\16<\31d\25\1\25\0\0\234\3.\1?\31\3\16:\5;\5L\v\35"..., 8192, 118611968) = 8192
pread(12, "\301\247\35\252\205\32\24G\232Z\2\n\33\0\0\2\301\247\35\4\336\0\0\0\0w\314#\302\0\212\301"..., 8192, 23699456) = 8192
pread(12, "\205\35\1\325\221%\0\17%\353W\2\23Q\245\205\35\256\205\35\1\325\221%\2\332\221%\0\17$\353"..., 8192, 23748608) = 8192
pread(12, "\0\25\277Z=\2G\34\3\1\241\305\35\252\305\35\1\353\226%\2\331\304\35\0\25\277Z=\2G!"..., 8192, 23756800) = 8192
pread(12, "\r\0\0\255\1w\361\37\2\303\1\227\2\216\r\0\0\255\1P\315\37\2\303\1\230\2\216\r\0\0\203"..., 8192, 23764992) = 8192
pread(12, "\20\rg\301S\2\200\1\367\3cL\10\7@\20\r\362_U\2\200\1\370\3\335L\10\7H\20\r"..., 8192, 23781376) = 8192
pread(12, "\37\1\275\306\37\2\350\326%\0a\31\225[\2\1\247\305\37\254\305\37\1\275\306\37\0\334\1\30\225["..., 8192, 23789568) = 8192
pread(12, "\0\30:\325\323W\2\322\r\1\300\211\30 -\331y]\2\322\17\1\24\0\0\0P-J}]\2"..., 8192, 23797760) = 8192
pread(12, "\6\10\356\312\4\7\10\342\313\37\6\10\263\315\37\7\10\263\315\37\6\10\342\313\37\7\10\321\334\32\6\10"..., 8192, 23805952) = 8192
pread(12, "\305!\2\357\224\4\310k\202\2\0167\23\0\1\246\205!\253\205!\1\320\324!\0\nJ\220\343\2\357"..., 8192, 23814144) = 8192
pread(12, "\2\253\310!\0(\32j\2\0\362\1774\306\17\2\253\310!\1\253\305!\264\305!\1\241\310!\2\253"..., 8192, 23822336) = 8192
pread(12, "\3\0\0\232\205\"\237\205\"\1\316\243\"\0\"\201\227V\2\361\f\5\0\370\267\2\261\205\"\266\205\""..., 8192, 23830528) = 8192
pread(12, "\345#\1\232\305\"\237\305\"\1\202\334#\0B\306) \2E\2/\1^\243\37\2\1\263\305\"\274"..., 8192, 23838720) = 8192
pread(12, "\205#\2\320\205#\2\352\204\36\0j\346\305\32\2\361\364\20\226\237\227\1\264\205#\2\320\205#\2\352"..., 8192, 23846912) = 8192

okay, according to tomhughes in #valgrind-dev, this is teh compressed debug info, and because it's compressed valgrind has to read the whole thing and decompress it to get what it needs.

<tomhughes> dwz is shared data - where data is duplicated across several programs the shared bits are extracted into the dwz
<tomhughes> your real problem is that genius (I'm guessing your a Debian victim here) has decided to compress your debug data, meaning that it all has to be read rather than just the required bits
<tomhughes> that probably interacts badly with extracting shared items to a dwz as well
<sage> ah.  this is centos 7.3 actually, but i'll see if we can fix the package not to do that
<tomhughes> because you have to read and decompress all the shared data
<sage> that makes sense, thanks
<tomhughes> redhat toolchains don't normally compress
<sage> we're building the package, so it's probably something in our tool.
<sage> i think i'm on the right track.. thanks tomhughes!
<tomhughes> look for --compress-debug-sections when linking

dwz appeard to be invoked by rpmbuild? from https://jenkins.ceph.com/job/ceph-dev-new-build/ARCH=x86_64,AVAILABLE_ARCH=x86_64,AVAILABLE_DIST=centos7,DIST=centos7,MACHINE_SIZE=huge/1598/consoleText,

+ /usr/lib/rpm/find-debuginfo.sh --strict-build-id -m --run-dwz --dwz-low-mem-die-limit 10000000 --dwz-max-die-limit 110000000 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.0.0-932-g8d6fb1d/rpm/el7/BUILD/ceph-12.0.0-932-g8d6fb1d
extracting debug info from /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.0.0-932-g8d6fb1d/rpm/el7/BUILDROOT/ceph-12.0.0-932.g8d6fb1d.el7.x86_64/usr/lib64/ceph/libceph-common.so.0
extracting debug info from /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos7/DIST/centos7/MACHINE_SIZE/huge/release/12.0.0-932-g8d6fb1d/rpm/el7/BUILDROOT/ceph-12.0.0-932.g8d6fb1d.el7.x86_64/usr/lib64/ceph/erasure-code/libec_jerasure.so
...

but i'm not sure why this is happening. also these failures seem to be new-ish... not sure what changed?

guess the redhat-rpm-config is updated in our build machine to 9.1.0-30 or up. which includes the fix of https://bugzilla.redhat.com/show_bug.cgi?id=833311.
so as suggested by dmick,

%_find_debuginfo_dwz_opts %{nil}

we should just disable dwz in the .spec, right?

debuginfo sizes collected from https://download.ceph.com/ and https://copr-be.cloud.fedoraproject.org/results/badone/Ceph-nightlies/fedora-25-x86_64/00517442-ceph/

opensuse splits the debuginfo into smaller pieces, see http://download.opensuse.org/repositories/filesystems:/ceph/openSUSE_Leap_42.1/x86_64/, all the debuginfo packages size 971MB in total. but the reason why the valgrind started to slow down is still a mystery, dwz support on rpm and valgrind was introduced back in 2012. and centos 7 has included them for a while. maybe we can abandon the monolithic approach to package all debuginfo into a single package ?

If someone can give me clear instructions on how to reproduce this (assume I'm dumb) or better yet give me access to an environment where this is happening I believe I should be able to gather more information about the exact nature of the issue, and possibly confirm that it is related to the size of the debuginfo and/or the fact that it is compressed. Remember that my teuthology foo is not great so try to be gentle. This also assumes we consider this a good use of my time.

If you'd like to get more information on the issue yourselves I would suggest a combination of "ps axHo %cpu,stat,pid,tid,pgid,ppid,comm,wchan" to identify the thread that is chewing the CPU (likely the problem thread) and gstack to dump out thread stacks and match the "tid" from ps output to the "LWP" number in gstack output. You may need to do this a few times to be sure you've pin-pointed the problematic code (this is the "poorman's profiler" technique, see http://poormansprofiler.org/). Once we identify the function we could use a systemtap to work out how long it is spending in the function calls involved and hopefully zero in on the exact nature of the issue. You'll need the valgrind debuginfo package loaded as well as the systemtap package if you want to use that (run "stap-prep" to get it set up).

teuthology-suite -s rados/verify --filter valgrind --limit 1 -p 10 -c wip-sage-testing

tail teuthology.log to see which machine it picks, and log in while the daemons are starting up.

FWIW debian does a -dbg packages for every subpackage (e.g., ceph-osd-dbg, ceph-test-dbg) and it is so much nicer!! if this is an option, let's do that? (it'll probably mean changing the install task to try either ceph-debuginfo or the various subpackages, since older versions will still have the big -debuginfo).

i guess more importantly, is there an reason we want/need the compressed dwz in the package? maybe we can just turn it off?

testing at http://pulpito.ceph.com/kchai-2017-03-02_16:25:12-rados:verify-wip-disable-dwz-kefu---basic-mira/

teuthology-suite --ceph wip-disable-dwz-kefu -s rados/verify --filter valgrind --limit 1 -p 10  --machine-type mira

the change is posted at https://github.com/ceph/ceph/pull/13748

2017-03-02T16:38:35.562 INFO:tasks.ceph:Waiting until ceph cluster ceph is healthy...
...
2017-03-02T16:38:56.947 DEBUG:teuthology.misc:6 of 6 OSDs are up

it took over 5 minutes to boot and active with dwz, see #19113.

turns out, to split the the single big debuginfo packages into subpackages, is not a trivial task. see https://bugzilla.redhat.com/show_bug.cgi?id=185590.

see also https://github.com/ceph/ceph/pull/42559