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 9274D3860825 for ; Fri, 8 Apr 2022 21:08:04 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.1 sourceware.org 9274D3860825 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 92A5C24023A; Fri, 8 Apr 2022 23:08:03 +0200 (CEST) From: Milian Wolff To: Mark Wielaard Cc: "Frank Ch. Eigler" , elfutils-devel@sourceware.org Subject: Re: caching failed lookups of debuginfo? Date: Fri, 08 Apr 2022 23:08:03 +0200 Message-ID: <19455068.ZVunK98tCv@milian-workstation> In-Reply-To: References: <4448277.fIUe8AKecr@milian-workstation> <2854938.4GpPBkblLQ@milian-workstation> MIME-Version: 1.0 Content-Type: multipart/signed; boundary="nextPart1939156.Q55iAj5TBu"; micalg="pgp-sha256"; protocol="application/pgp-signature" X-Spam-Status: No, score=1.1 required=5.0 tests=BAYES_00, KAM_DMARC_STATUS, KAM_LAZY_DOMAIN_SECURITY, KAM_LOTSOFHASH, 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-Level: * 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 21:08:06 -0000 --nextPart1939156.Q55iAj5TBu Content-Transfer-Encoding: 7Bit Content-Type: text/plain; charset="us-ascii"; protected-headers="v1" From: Milian Wolff To: Mark Wielaard Subject: Re: caching failed lookups of debuginfo? Date: Fri, 08 Apr 2022 23:08:03 +0200 Message-ID: <19455068.ZVunK98tCv@milian-workstation> In-Reply-To: On Freitag, 8. April 2022 22:59:55 CEST Mark Wielaard wrote: > Hi Milian, > > On Fri, Apr 08, 2022 at 10:45:10PM +0200, Milian Wolff wrote: > > 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? > > That is certainly not what should happen once the cache is filled. > Could you run with DEBUGINFOD_VERBOSE=1 to see what is being fetched and > why? My first mail showed this already. But here is one such block: ``` debuginfod_find_debuginfo 85766e9d8458b16e9c7ce6e07c712c02b8471dbc server urls "https://debuginfod.archlinux.org/" checking build-id checking cache dir /home/milian/.cache/debuginfod_client using timeout 90 init server 0 https://debuginfod.archlinux.org/buildid url 0 https://debuginfod.archlinux.org/buildid/ 85766e9d8458b16e9c7ce6e07c712c02b8471dbc/debuginfo query 1 urls in parallel server response HTTP response code said error url 0 The requested URL returned error: 404 not found No such file or directory (err=-2) ``` I see this repeated multiple times - both for different files and for the same file. I.e.: ``` $ /home/milian/projects/compiled/other/lib/heaptrack/libexec/ heaptrack_interpret < heaptrack.kate.52068.raw |& egrep "^url 0 https" | sort | uniq -c | sort -n ``` Produces this output here locally for me: https://invent.kde.org/-/snippets/ 2153 I can reproduce it now suddenly with debuginfod-find too: ``` $ debuginfod-find debuginfo 85766e9d8458b16e9c7ce6e07c712c02b8471dbc debuginfod_find_debuginfo 85766e9d8458b16e9c7ce6e07c712c02b8471dbc server urls "https://debuginfod.archlinux.org/" checking build-id checking cache dir /home/milian/.cache/debuginfod_client using timeout 90 init server 0 https://debuginfod.archlinux.org/buildid url 0 https://debuginfod.archlinux.org/buildid/ 85766e9d8458b16e9c7ce6e07c712c02b8471dbc/debuginfo query 1 urls in parallel server response HTTP response code said error url 0 The requested URL returned error: 404 not found No such file or directory (err=-2) Server query failed: No such file or directory ``` I do see an empty `/home/milian/.cache/debuginfod_client/ 85766e9d8458b16e9c7ce6e07c712c02b8471dbc/debuginfo` file. But the server is still queried (i.e. rerunning the above command always produces the same output for me). The lookup is costly too at ~70ms overall: ``` $ perf stat -r 5 debuginfod-find debuginfo 85766e9d8458b16e9c7ce6e07c712c02b8471dbc 7.83 msec task-clock # 0.114 CPUs utilized ( +- 4.75% ) ... 0.06857 +- 0.00187 seconds time elapsed ( +- 2.73% ) ``` Thanks -- Milian Wolff mail@milianw.de http://milianw.de --nextPart1939156.Q55iAj5TBu 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/HGdOX8FAmJQpDMACgkQ8zYW/HGd OX9LjQ/+OzLmlXhV77mM5H6alr3gzeAJNzm8Jl4QdjqOsVZl1Ycw06c9ftw7D8zH I6jt4Xa+WwgQfeQm1KXpo/DeHZeZBCqediVUsuPXpzTsIVcsJGTlVKdSb7ZUlm+L 64Yacd1QG8/N9u9I1CcRnPrm5TXxd8AhdHcWofQBd3lJ9py/sC7pygediONaek+H kZeK6Xh8Cq5V5/CStxAnWvaaiTHnx7SCdZj8jSeyv9ZLZ4G6G9vzMHl0czImPTi4 AUvRGDGyifbJypq077gtB/noWAw++ZXm3VKvAUhPJo92+6R7eqhIxrQj9HXfKqqu e86GROwQmuqxHAf1GH0rvxkyfq6LIvG/1sWgfDeygpwH5KexDEdHbOSYg/8vUpTi 74ktJnX1DapxblEKPCMXO01y4YXtZUZVMSZfwN0ZwMtNCf0G7aum5SAScd4N0QO+ jiVkaHT0jDofWjrVaKtLJRIhiybzy2evu+DsA1c+rsqMt5CWLSoc0vDmTwxtrjGl WXv/yNw/+hxfxQe33LnqRJwZ5qLhOHsRANYOjLUpx/Hf2oM6HJmTt6OnqxKDBSeM R8gYWDaaDF+z7PLjFgrIaXEgjBBXdEfz8ioqyOow56vMhKB5sJGbQ/QLuu5tF2g0 x5J2m0HYmKVTbxBDdNG7ABozTN9CQkd9r50iqsCUtTyfe+HSdVQ= =7B9t -----END PGP SIGNATURE----- --nextPart1939156.Q55iAj5TBu--