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