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 BF5483858D3C for ; Fri, 8 Apr 2022 19:58:16 +0000 (GMT) DMARC-Filter: OpenDMARC Filter v1.4.1 sourceware.org BF5483858D3C 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 CE93B24023A for ; Fri, 8 Apr 2022 21:58:15 +0200 (CEST) From: Milian Wolff To: elfutils-devel@sourceware.org Subject: caching failed lookups of debuginfo? Date: Fri, 08 Apr 2022 21:58:15 +0200 Message-ID: <4448277.fIUe8AKecr@milian-workstation> MIME-Version: 1.0 Content-Type: multipart/signed; boundary="nextPart3723353.ct2uI1TupA"; micalg="pgp-sha256"; protocol="application/pgp-signature" X-Spam-Status: No, score=1.0 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-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 19:58:18 -0000 --nextPart3723353.ct2uI1TupA Content-Transfer-Encoding: 7Bit Content-Type: text/plain; charset="us-ascii"; protected-headers="v1" From: Milian Wolff To: elfutils-devel@sourceware.org Subject: caching failed lookups of debuginfo? Date: Fri, 08 Apr 2022 21:58:15 +0200 Message-ID: <4448277.fIUe8AKecr@milian-workstation> Hey all, 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. Now, on consecutive runs, nothing should be downloaded anymore. But I notice that there is still a huge slowdown incurred when enabled `DEBUGINFOD_URLS`: With DEBUGINFOD_URLS set: ``` perf stat ./heaptrack_interpret ... 5,765.36 msec task-clock # 0.707 CPUs utilized ... 8.154873275 seconds time elapsed 5.477158000 seconds user 0.271662000 seconds sys ``` Without DEBUGINFOD_URLS set: ``` perf stat ./heaptrack_interpret ... 2,460.09 msec task-clock # 0.999 CPUs utilized ... 2.461661784 seconds time elapsed 2.334429000 seconds user 0.119698000 seconds sys ``` Note the significantly increased wall-time in the first case. The second case (without debuginfod) has basically zero off-CPU time and significantly reduced on-CPU time too. Looking at the off-CPU time flame graph, and enabling verbose debuginfod output lets me come to the conclusion, that the issue above is due to some libraries simply not having any debug information uploaded. I.e. I see dozens of reports such as: ``` debuginfod_find_debuginfo 2e245c2bf12f95fd8ab79b3a4be99524677cbd70 server urls "https://debuginfod.archlinux.org/" checking build-id checking cache dir /home/milian/.debuginfod_client_cache using timeout 90 init server 0 https://debuginfod.archlinux.org/buildid url 0 https://debuginfod.archlinux.org/buildid/ 2e245c2bf12f95fd8ab79b3a4be99524677cbd70/debuginfo query 1 urls in parallel Downloading | server response HTTP response code said error url 0 The requested URL returned error: 404 not found No such file or directory (err=-2) ``` 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. What's worse, I'm seeing multiple lookups for the same buildid *within the same process*. I.e.: ``` export DEBUGINFOD_VERBOSE=1 ./heaptrack_interpret ... |& egrep "^url 0 https" | sort | uniq -c | sort ... 6 url 0 https://debuginfod.archlinux.org/buildid/ 7f4b16b4b407cbae2d7118d6f99610e29a18a56a/debuginfo 8 url 0 https://debuginfod.archlinux.org/buildid/ c09c6f50f6bcec73c64a0b4be77eadb8f7202410/debuginfo 14 url 0 https://debuginfod.archlinux.org/buildid/ 85766e9d8458b16e9c7ce6e07c712c02b8471dbc/debuginfo ``` Here, we are paying roughly `14 * 0.2s = 2.8s` just for a single library. Can we find a way to improve this situation somehow generically? I would personally even be OK with caching the 404 error case locally for some time (say, one hour or one day or ...). Then at least we would at most pay this cost once per library, and not multiple times. And rerunning the analysis a second time would become much faster again. Was there a deliberate decision against caching negative server side lookups? Thanks -- Milian Wolff mail@milianw.de http://milianw.de --nextPart3723353.ct2uI1TupA 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/HGdOX8FAmJQk9cACgkQ8zYW/HGd OX+dSw/9FH5/6G3I0toKIwZLKJq2a4Q82vN1jSEl/6rxDkZ8ymsyn9N3TsMJ0XCz 912Sa97DzAWwQYqUUlt8Q5THyAfGzSZoWyNzt7fyTz0Z2KyIuHNMA++5Tf+6N8kG oQvo/3+9eELxyFoDu6CWXZ45gM5lP7+3X9vKwiT1umquAiyOyeGFKYcFeZdHfBJz XCqoYm4M0Sjuhk7wKS6iKUQeiROra+JMZhtWGLFJUXF9pyhOeXzrZBKMV9KgWhbz 8jfyYODGKoumZYtlfbXF1WDHFVNh69miI8uibZNWrnZFesZoANfQfQt6DGsep5va Z8P0dEG7kUpDwlQNBXXHLi+mlUtlAb+yLrSD3C506tuEYHKN2Dq7Bpk2xmyiMve3 jplXX7Rw9GIZmpZJeeNVoI0gvXp1SHlsv+9bAb586/lGzXtijGTysXd2nSW6ce4A deSB09nEr/Uc+BJWOgl80ViqmZbiCIEcS6w1vYceRXSqed9ZtXcQDk/Xn+6UXqrP XnzcRHGWfLPsV4COjgvDPxRlbmcyw+l8/9Rzh7Av5c8g7/3oVm6o33zll01ZeU5v mPkrVd3GKOz3PQ0RjBCNlGDNdqgVP9xvmbKdC9eXfX8L4fk5kS4g5sl/ARhyhYbr wENwmPqJNMna55e9M1GtHVv5ZH3RJlgfgbKV+GsGcGS7Qo0YQ58= =mZKA -----END PGP SIGNATURE----- --nextPart3723353.ct2uI1TupA--