Index files are not used in the session where they were created

Index files are not used in the session where they were created

[Dmitry Neverov via Gdb]

I'm investigating whether index-caches help with slow symbols
loading (https://sourceware.org/bugzilla/show_bug.cgi?id=30520).

They seem to help, but only on the second gdb run. When I start a
debug session for the first time with an empty ~/.caches/gdb
directory, I can see from logs that gdb tries to read index
files, fails because they don't exist, and then writes index to
disk. The index is saved in a few seconds.

If I then try loading children of a variable causing a slow symbol
lookup, the lookup is still slow. Even though the index is ready
and is saved to disk.

If I restart gdb after the index is written, then gdb picks it
up, and symbol loading is much faster - a few seconds instead of
a minute.

Is there a way to use the created index without gdb restart?

-- 
Dmitrii Neverov

Re: Index files are not used in the session where they were created

[Tom Tromey]

>>>>> "Dmitry" == Dmitry Neverov via Gdb <gdb@sourceware.org> writes:

Dmitry> I'm investigating whether index-caches help with slow symbols
Dmitry> loading (https://sourceware.org/bugzilla/show_bug.cgi?id=30520).

...

Dmitry> If I then try loading children of a variable causing a slow symbol
Dmitry> lookup, the lookup is still slow. Even though the index is ready
Dmitry> and is saved to disk.

Dmitry> If I restart gdb after the index is written, then gdb picks it
Dmitry> up, and symbol loading is much faster - a few seconds instead of
Dmitry> a minute.

Dmitry> Is there a way to use the created index without gdb restart?

Actually I'm surprised to hear that the index makes a difference in this
case.  It would be good to understand this better -- maybe there's a
bug.

The reason I say that is that gdb has a "two phase" DWARF reader.

The first phase scans the DWARF, building a symbol table.  In the index
case, this just means mapping in the index (and maybe doing a bit of
processing).

Currently, gdb will pause until this phase is complete.  That is, if you
run "gdb -nx" and use "file some-executable", the prompt won't return
until scanning is done.


After this is what is called "full CU expansion".  If you print a
variable or set a breakpoint (or otherwise cause gdb to need debug
info), gdb will re-read the DWARF for selected compilation units,
expanding the ones it thinks are necessary.

This phase only has a single implementation -- it does not depend on how
the scanning was done.  This is why it's surprising that the index would
make a difference here.

That said, the two scanners might differ on how they select which CUs to
expand.  I'd guess that is what you are seeing.  Maybe it means that the
index is failing in some situation -- or maybe it means we could make
the DWARF scanner implementation a bit faster by having it expand less.

To figure this out, we'd probably need a test case.  Maybe comparing the
results between the two scenarios with "set debug symtab-create on"
would indicate something.

Tom

Re: Index files are not used in the session where they were created

[Dmitry Neverov via Gdb]

Tom> To figure this out, we'd probably need a test case.  Maybe comparing
the
Tom> results between the two scenarios with "set debug symtab-create on"
Tom> would indicate something.

I have a reproducer, but it is somewhat tricky to build. It is
also not my program, so I'm not sure if I can simplify it.

The program is KiCad (https://gitlab.com/kicad/code/kicad.git).
Build dependencies for Ubuntu can be obtained from the packaging
files: https://dev-docs.kicad.org/en/build/linux/#_dependencies.

Once KiCad is built I run the following commands in gdb:

(gdb) file /home/nd/w/CLionProjects/kicad/build/debug/pcbnew/pcbnew
(gdb) b /home/nd/w/CLionProjects/kicad/pcbnew/footprint_edit_frame.cpp:114
(gdb) run

When KiCad's window is opened I invoke the menu item "Tools >
Footprint Editor" to hit the created breakpoint, and then run:

(gdb) interpreter-exec mi2 "-var-create var1_this * \"this\""
(gdb) interpreter-exec mi2 "-var-list-children --all-values \"var1_this\"
-1 -1"
(gdb) interpreter-exec mi2 "-var-list-children --all-values
\"var1_this.private\" 0 8"

The last command takes most of the time. The .gdbinit only sets up logging:

set trace-commands on
set logging overwrite on
set logging debugredirect on
set logging enabled on
set debug symtab-create 1

I've captured the logs, they are quite big, the zip (15Mb) is here:
https://drive.google.com/file/d/1Cz-HOOqus6xwf_eIjBqcs727w8aOqco4/view?usp=sharing
.

There are 3 files in archive:

- gdb.txt.index-cache-disabled - the slow run with index-cache
  disabled

- gdb.txt.index-cache-enabled-run1 - the first run with
  index-cache enabled - it is still slow

- gdb.txt.index-cache-enabled-run2 - the second run with
  index-cache enabled - fast

Re: Index files are not used in the session where they were created

[Dmitry Neverov via Gdb]

Hi Tom,

I've debugged it a bit more and the number of CUs is indeed
different. Without indexes gdb loads 506 CUs during one slow
symbol lookup, with indexes no CUs are
loaded ('qf_require_partial_symbols()' returns empty list inside
'objfile::lookup_symbol'). Is it something expected? If not,
could you please suggest how to debug it further?


On Tue, Aug 1, 2023 at 8:42 AM Dmitry Neverov <dmitry.neverov@jetbrains.com>
wrote:

> Tom> To figure this out, we'd probably need a test case.  Maybe comparing
> the
> Tom> results between the two scenarios with "set debug symtab-create on"
> Tom> would indicate something.
>
> I have a reproducer, but it is somewhat tricky to build. It is
> also not my program, so I'm not sure if I can simplify it.
>
> The program is KiCad (https://gitlab.com/kicad/code/kicad.git).
> Build dependencies for Ubuntu can be obtained from the packaging
> files: https://dev-docs.kicad.org/en/build/linux/#_dependencies.
>
> Once KiCad is built I run the following commands in gdb:
>
> (gdb) file /home/nd/w/CLionProjects/kicad/build/debug/pcbnew/pcbnew
> (gdb) b /home/nd/w/CLionProjects/kicad/pcbnew/footprint_edit_frame.cpp:114
> (gdb) run
>
> When KiCad's window is opened I invoke the menu item "Tools >
> Footprint Editor" to hit the created breakpoint, and then run:
>
> (gdb) interpreter-exec mi2 "-var-create var1_this * \"this\""
> (gdb) interpreter-exec mi2 "-var-list-children --all-values \"var1_this\"
> -1 -1"
> (gdb) interpreter-exec mi2 "-var-list-children --all-values
> \"var1_this.private\" 0 8"
>
> The last command takes most of the time. The .gdbinit only sets up logging:
>
> set trace-commands on
> set logging overwrite on
> set logging debugredirect on
> set logging enabled on
> set debug symtab-create 1
>
> I've captured the logs, they are quite big, the zip (15Mb) is here:
>
> https://drive.google.com/file/d/1Cz-HOOqus6xwf_eIjBqcs727w8aOqco4/view?usp=sharing
> .
>
> There are 3 files in archive:
>
> - gdb.txt.index-cache-disabled - the slow run with index-cache
>   disabled
>
> - gdb.txt.index-cache-enabled-run1 - the first run with
>   index-cache enabled - it is still slow
>
> - gdb.txt.index-cache-enabled-run2 - the second run with
>   index-cache enabled - fast
>
>

Re: Index files are not used in the session where they were created

[Dmitry Neverov via Gdb]

Please ignore my previous message regarding an empty
qf_require_partial_symbols(). I think I was wrong and now understand a
bit better where the difference in time comes from.

In my case lookup is slow for a symbol with name wxObjectDataPtr.

When index is not used, the
cooked_index_functions::expand_symtabs_matching() finds many entries
of the form 'wxObjectDataPtr<wxBitmapBundleImpl>'. Such entries don't have
a parent entry, and so they cannot be filtered out, and the
dw2_expand_symtabs_matching_one() is called.

Inside the expansion callback (lambda in objfile::lookup_symbol) the
block_find_symbol() is called which eventually calls
cp_fq_symbol_name_matches(). cp_fq_symbol_name_matches() takes
templates into account and decides that
wxObjectDataPtr<wxBitmapBundleImpl> doesn't actually match the wxObjectDataPtr,
and so no symbols from symtab match.

When index is used, the check for templates happens in
dw2_expand_symtabs_matching_symbol(). The name_matcher
(default_symbol_name_matcher) is called before deciding to expand the
symtab. So entries like 'wxObjectDataPtr<wxBitmapBundleImpl>' don't
cause expansion for lookup name wxObjectDataPtr.

I wonder if it is possible to check templates before symtab expansion in
the no-index case as well?

Re: Index files are not used in the session where they were created

[Tom Tromey]

>>>>> "Dmitry" == Dmitry Neverov via Gdb <gdb@sourceware.org> writes:

Dmitry> Please ignore my previous message regarding an empty
Dmitry> qf_require_partial_symbols(). I think I was wrong and now understand a
Dmitry> bit better where the difference in time comes from.

Thank you for looking into this.

Dmitry> When index is used, the check for templates happens in
Dmitry> dw2_expand_symtabs_matching_symbol(). The name_matcher
Dmitry> (default_symbol_name_matcher) is called before deciding to expand the
Dmitry> symtab. So entries like 'wxObjectDataPtr<wxBitmapBundleImpl>' don't
Dmitry> cause expansion for lookup name wxObjectDataPtr.

Dmitry> I wonder if it is possible to check templates before symtab expansion in
Dmitry> the no-index case as well?

This sounds related to
https://sourceware.org/bugzilla/show_bug.cgi?id=31010

I think it would be good to have a separate bug for your case though.

I am not sure if it's possible to do this, but I think it would be worth
investigating.

Tom

Re: Index files are not used in the session where they were created

[Dmitry Neverov via Gdb]

> I think it would be good to have a separate bug for your case though.

I investigated it in the scope of
https://sourceware.org/bugzilla/show_bug.cgi?id=30520.
Should I still file a dedicated issue?

Re: Index files are not used in the session where they were created

[Dmitry Neverov via Gdb]

I think I found why index files are not used in the debug session
where they are created. Objfile.qf is initialized at

  dwarf2_initialize_objfile read.c:5396
  elf_symfile_read_dwarf2 elfread.c:1199
  elf_symfile_read elfread.c:1343
  read_symbols symfile.c:773
  syms_from_objfile_1 symfile.c:968
  syms_from_objfile symfile.c:985
  symbol_file_add_with_addrs symfile.c:1088
  symbol_file_add_from_bfd symfile.c:1168
  symbol_file_add symfile.c:1181
  symbol_file_add_main_1 symfile.c:1205
  symbol_file_command symfile.c:1653
  file_command exec.c:554
  do_simple_func cli-decode.c:95
  cmd_func cli-decode.c:2543
  execute_command top.c:690
  execute_control_command_1 cli-script.c:537
  execute_control_command cli-script.c:709
  execute_control_commands cli-script.c:410
  execute_user_command cli-script.c:460
  execute_command top.c:664
  command_handler event-top.c:616
  command_line_handler event-top.c:852
  tui_command_line_handler tui-interp.c:104
  gdb_rl_callback_handler event-top.c:246
  rl_callback_read_char callback.c:290
  gdb_rl_callback_read_char_wrapper_noexcept event-top.c:188
  gdb_rl_callback_read_char_wrapper event-top.c:221
  stdin_event_handler event-top.c:541
  handle_file_event event-loop.cc:573
  gdb_wait_for_event event-loop.cc:694
  gdb_do_one_event event-loop.cc:264
  start_event_loop main.c:411
  captured_command_loop main.c:471
  captured_main main.c:1330
  gdb_main main.c:1345
  main gdb.c:32

Since no gdb-index is created yet, qf is updated like this:

objfile->qf.push_front (make_cooked_index_funcs ());

After that the gdb-index is created at

  dwarf2_build_psymtabs read.c:5437
  cooked_index_functions::read_partial_symbols read.c:18601
  objfile::require_partial_symbols symfile-debug.c:582
  read_symbols symfile.c:795
  syms_from_objfile_1 symfile.c:968
  syms_from_objfile symfile.c:985
  symbol_file_add_with_addrs symfile.c:1088
  symbol_file_add_from_bfd symfile.c:1168
  symbol_file_add symfile.c:1181
  symbol_file_add_main_1 symfile.c:1205
  symbol_file_command symfile.c:1653
  file_command exec.c:554
  do_simple_func cli-decode.c:95
  cmd_func cli-decode.c:2543
  execute_command top.c:690
  execute_control_command_1 cli-script.c:537
  execute_control_command cli-script.c:709
  execute_control_commands cli-script.c:410
  execute_user_command cli-script.c:460
  execute_command top.c:664
  command_handler event-top.c:616
  command_line_handler event-top.c:852
  tui_command_line_handler tui-interp.c:104
  gdb_rl_callback_handler event-top.c:246
  rl_callback_read_char callback.c:290
  gdb_rl_callback_read_char_wrapper_noexcept event-top.c:188
  gdb_rl_callback_read_char_wrapper event-top.c:221
  stdin_event_handler event-top.c:541
  handle_file_event event-loop.cc:573
  gdb_wait_for_event event-loop.cc:694
  gdb_do_one_event event-loop.cc:264
  start_event_loop main.c:411
  captured_command_loop main.c:471
  captured_main main.c:1330
  gdb_main main.c:1345
  main gdb.c:32

but objfile.qf is not updated and the gdb-index is not used in
this debug session.

Is it an expected behavior and gdb indexes should be created
before the debug session to be used? Or maybe there is a way to
make gdb to use them?

Dmitry

Re: Index files are not used in the session where they were created

[Dmitry Neverov via Gdb]

> I am not sure if it's possible to do this, but I think it would be worth
> investigating.

Is it wrong to do something like the following in the 'if
(symbol_matcher == nullptr)'
branch in cooked_index_functions::expand_symtabs_matching?

  enum language cu_lang = entry->per_cu->lang(false);
  if (cu_lang != language_unknown && lookup_name->match_type() ==
symbol_name_match_type::FULL)
    {
      const language_defn *lang_def = language_def (cu_lang);
      symbol_name_matcher_ftype *name_matcher =
lang_def->get_symbol_name_matcher (lookup_name_without_params);
      auto_obstack temp_storage;
      if (!name_matcher(entry->full_name(&temp_storage),
lookup_name_without_params, nullptr))
        continue;
    }

Dmitry