From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from dd14210.kasserver.com (dd14210.kasserver.com [85.13.138.83]) by sourceware.org (Postfix) with ESMTPS id 3EE88385781D for ; Fri, 8 Apr 2022 20:45:12 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.1 sourceware.org 3EE88385781D Authentication-Results: sourceware.org; dmarc=none (p=none dis=none) header.from=milianw.de Authentication-Results: sourceware.org; spf=none smtp.mailfrom=milianw.de Received: from milian-workstation.localnet (p54a1bbed.dip0.t-ipconnect.de [84.161.187.237]) by dd14210.kasserver.com (Postfix) with ESMTPSA id 4919C240533; Fri, 8 Apr 2022 22:45:11 +0200 (CEST) From: Milian Wolff To: "Frank Ch. Eigler" Cc: elfutils-devel@sourceware.org Subject: Re: caching failed lookups of debuginfo? Date: Fri, 08 Apr 2022 22:45:10 +0200 Message-ID: <2854938.4GpPBkblLQ@milian-workstation> In-Reply-To: <20220408200527.GC23295@redhat.com> References: <4448277.fIUe8AKecr@milian-workstation> <20220408200527.GC23295@redhat.com> MIME-Version: 1.0 Content-Type: multipart/signed; boundary="nextPart1649500461.I3H33CtYLs"; micalg="pgp-sha256"; protocol="application/pgp-signature" X-Spam-Status: No, score=0.9 required=5.0 tests=BAYES_00, KAM_DMARC_STATUS, KAM_LAZY_DOMAIN_SECURITY, RCVD_IN_BARRACUDACENTRAL, RCVD_IN_DNSWL_LOW, SPF_HELO_NONE, SPF_NONE, TXREP, T_SCC_BODY_TEXT_LINE autolearn=no autolearn_force=no version=3.4.4 X-Spam-Checker-Version: SpamAssassin 3.4.4 (2020-01-24) on server2.sourceware.org X-BeenThere: elfutils-devel@sourceware.org X-Mailman-Version: 2.1.29 Precedence: list List-Id: Elfutils-devel mailing list List-Unsubscribe: , List-Archive: List-Help: List-Subscribe: , X-List-Received-Date: Fri, 08 Apr 2022 20:45:15 -0000 --nextPart1649500461.I3H33CtYLs Content-Transfer-Encoding: 7Bit Content-Type: text/plain; charset="us-ascii"; protected-headers="v1" From: Milian Wolff To: "Frank Ch. Eigler" Cc: elfutils-devel@sourceware.org Subject: Re: caching failed lookups of debuginfo? Date: Fri, 08 Apr 2022 22:45:10 +0200 Message-ID: <2854938.4GpPBkblLQ@milian-workstation> In-Reply-To: <20220408200527.GC23295@redhat.com> On Freitag, 8. April 2022 22:05:27 CEST Frank Ch. Eigler wrote: > Hi - > > > another debuginfod related question, but unrelated to the other thread I > > started earlier today. In a work branch I have ported my heaptrack > > profiler > > over to elfutils. I have then run the analyzer that uses elfutils (and > > thus > > debuginfod internally via dwfl) on a recorded data file to have it > > download > > all the debug info files it can find. > > Nice. > > > These negative lookups are not cached. Meaning rerunning the same process > > using dwfl and debuginfod on the same data would always incur a > > significant > > slowdown, as we would again and again try to look for something that's not > > there. The lookups take roughly ~200ms for me to realize the data is not > > on > > the server. > > That's not correct, as of elfutils 0.184 (commit 5f72c51a7e5c0), > with some more recent tweaks in (commit 7d64173fb11c6). I am running elfutils 0.186 here and I definitely saw this happening (that's where the output from my previous mail came from after all). I've now wiped my local debuginfod cache and tried to replicate it, but magically the repeated lookups are gone. This is very mysterious... Nevertheless, I clearly still see a significant overhead of having DEBUGINFOD_URLS set, even after the first run that should have populated the cache, no? I.e. check this out: ``` $ export DEBUGINFOD_URLS=https://debuginfod.archlinux.org/ $ perf stat -r 5 ./heaptrack_interpret ... 5,993.67 msec task-clock # 0.696 CPUs utilized ( +- 0.22% ) 301 context-switches # 50.567 /sec ( +- 7.47% ) 3 cpu-migrations # 0.504 /sec ( +- 19.44% ) 145,574 page-faults # 24.456 K/sec ( +- 0.01% ) 25,026,712,955 cycles # 4.204 GHz ( +- 0.14% ) (83.27%) 357,786,453 stalled-cycles-frontend # 1.43% frontend cycles idle ( +- 1.77% ) (83.39%) 4,851,145,553 stalled-cycles-backend # 19.44% backend cycles idle ( +- 0.99% ) (83.35%) 64,893,827,473 instructions # 2.60 insn per cycle # 0.07 stalled cycles per insn ( +- 0.05% ) (83.29%) 14,234,732,114 branches # 2.391 G/sec ( +- 0.04% ) (83.30%) 111,326,964 branch-misses # 0.78% of all branches ( +- 0.17% ) (83.44%) 8.6057 +- 0.0667 seconds time elapsed ( +- 0.77% ) ``` versus: ``` $ unset DEBUGINFOD_URLS $ perf stat -r 5 ./heaptrack_interpret ... 2,505.36 msec task-clock # 1.009 CPUs utilized ( +- 0.48% ) 542 context-switches # 218.486 /sec ( +- 17.87% ) 1 cpu-migrations # 0.403 /sec ( +- 24.49% ) 50,712 page-faults # 20.443 K/sec ( +- 0.02% ) 10,821,713,676 cycles # 4.362 GHz ( +- 0.15% ) (83.24%) 129,975,157 stalled-cycles-frontend # 1.20% frontend cycles idle ( +- 4.86% ) (83.37%) 1,719,256,978 stalled-cycles-backend # 15.93% backend cycles idle ( +- 1.33% ) (83.38%) 28,947,652,758 instructions # 2.68 insn per cycle # 0.06 stalled cycles per insn ( +- 0.03% ) (83.40%) 6,118,310,875 branches # 2.466 G/sec ( +- 0.03% ) (83.38%) 46,907,166 branch-misses # 0.77% of all branches ( +- 0.16% ) (83.30%) 2.4833 +- 0.0124 seconds time elapsed ( +- 0.50% ) ``` There is clearly still a significant slowdown imposed by having debuginfod enabled - even after the first run. Is this expected? My assumption was: Only the first run would be potentially slow, then everything is cached locally. In the off-CPU flame graphs I clearly see this callchain when DEBUGINFOD_URLS is set: ``` dwfl_standard_find_debuginfo > debuginfod_query_server > curl_multi_wait ``` This accounts for ~2.5s of off-CPU time in my case. If you are saying that negative lookups are cached, then what is this? Why would a second run of the same dwfl-using application with the same input data keep querying the server? Thanks -- Milian Wolff mail@milianw.de http://milianw.de --nextPart1649500461.I3H33CtYLs Content-Type: application/pgp-signature; name="signature.asc" Content-Description: This is a digitally signed message part. Content-Transfer-Encoding: 7Bit -----BEGIN PGP SIGNATURE----- iQIzBAABCAAdFiEEezawi1aUvUGg3A1+8zYW/HGdOX8FAmJQntcACgkQ8zYW/HGd OX9r3g/8Ctrov/VLzbiswVJ8myC0tHMTHy+CoHYPURaXCsVSaS0FBCQXT4mpUcsJ +0BuoGGyia7mY06dyqZjE3llDPChoPzyNNOxjgItITgxzPPcYyhz5xVVWkercnl4 aRUkeX8CBpxy95oriJjtrgpppTgkJo77xkqVhBFp1NMg4p6m8tFsYOFSN1lTwDpH edU6/UvuiI9XiOakERy6qZoGFNHp7jQstMTeZz5W6ckubOZDwnOZzytGNg5vaBNc r/q+Nkn6wcufm8gLRbc6TawlCqaRaOtZ9MRvzJMGqy+uAn6iRuTJ+4DD/go4axdi q8qGUHd9KkLREiPpiTUxB3eC8/7rPtk+g3KgwkRxIXnlj2c2ArAkPfFZPFFRv6VY bvIC62CiLOeE5EiWtQp6J5DnLAHSE47LSB3vsmL4FssxiGgVT5swtjp2rbpCUhHp Ts8D0WQqVLG+cwdZ+RkCFIOfu9GD3at04ALlJyTK2u06wMXbuMXAZ5PwACgxR9bK p8m6q1CJACxuOeeHM/nqW/+qtlXflnUK/M3TM8SSL7L2BtSNehVBlKfSdLdneqkN 9zsSTaMuW4zsV0dD7yK0YH4ZcEmh5OBnRzwsn1ImXSyjBgy1quuEhsJU25e5tBhm AR5mH5VSMG8vRhhNgZXWPzvXYvSRk9vvUL1jN5HIiPuI86bTF0k= =K0l1 -----END PGP SIGNATURE----- --nextPart1649500461.I3H33CtYLs--