Re: [patch] Fix 100x slowdown regression on DWZ files

[Doug Evans <dje at google dot com>]

Jan Kratochvil writes:
 > Hi,
 > 
 > Bug 16405 - backtrace takes GBs and minutes with dwz -m (edit) 
 > https://sourceware.org/bugzilla/show_bug.cgi?id=16405
 > 
 > Since Fedora started to use DWZ DWARF compressor:
 > 	http://fedoraproject.org/wiki/Features/DwarfCompressor
 > GDB has slowed down a lot.  To make it clear - DWZ is DWARF structure
 > rearrangement, "compressor" does not mean any zlib style data compression.
 > 
 > This patch reduces LibreOffice backtrace from 5 minutes to 3 seconds (100x)
 > and it also reduces memory consumption 20x.
 > [ benchmark is at the bottom of this mail ]
 > 
 > Example of DWZ output:
 > ------------------------------------------------------------------------------
 >   Compilation Unit @ offset 0xc4:
 >  <0><cf>: Abbrev Number: 17 (DW_TAG_partial_unit)
 >     <d0>   DW_AT_stmt_list   : 0x0
 >     <d4>   DW_AT_comp_dir    : (indirect string, offset: 0x6f): /usr/src/debug/gdb-7.7.1/build-x86_64-redhat-linux-gnu/gdb
 >  <1><d8>: Abbrev Number: 9 (DW_TAG_typedef)
 >     <d9>   DW_AT_name        : (indirect string, offset: 0x827dc): size_t
 >     <dd>   DW_AT_decl_file   : 4
 >     <de>   DW_AT_decl_line   : 212
 >     <df>   DW_AT_type        : <0xae>
 > 
 >   Compilation Unit @ offset 0xe4:
 >  <0><ef>: Abbrev Number: 13 (DW_TAG_partial_unit)
 >     <f0>   DW_AT_stmt_list   : 0x0
 >     <f4>   DW_AT_comp_dir    : (indirect string, offset: 0x6f): /usr/src/debug/gdb-7.7.1/build-x86_64-redhat-linux-gnu/gdb
 >  <1><f8>: Abbrev Number: 45 (DW_TAG_typedef)
 >     <f9>   DW_AT_name        : (indirect string, offset: 0x251): __off_t
 >     <fd>   DW_AT_decl_file   : 3
 >     <fe>   DW_AT_decl_line   : 131
 >     <ff>   DW_AT_type        : <0x68>
 > 
 >   Compilation Unit @ offset 0x62d9f9:
 >  <0><62da04>: Abbrev Number: 20 (DW_TAG_compile_unit)
 > [...]
 >     <62da12>   DW_AT_low_pc      : 0x807e10
 >     <62da1a>   DW_AT_high_pc     : 134
 >     <62da1c>   DW_AT_stmt_list   : 0xf557e
 >  <1><62da20>: Abbrev Number: 7 (DW_TAG_imported_unit)
 >     <62da21>   DW_AT_import      : <0xcf>       [Abbrev Number: 17]
 > ------------------------------------------------------------------------------
 > 
 > One can see all DW_TAG_partial_unit have DW_AT_stmt_list 0x0 which causes
 > repeated decoding of that .debug_line unit on each DW_TAG_imported_unit.
 > 
 > This was OK before as each DW_TAG_compile_unit has its own .debug_line unit.
 > But since the introduction of DW_TAG_partial_unit by DWZ one should cache
 > read-in DW_AT_stmt_list .debug_line units.
 > 
 > Fortunately one does not need to cache whole
 > 	struct linetable *symtab->linetable
 > and other data from .debug_line mapping PC<->lines
 > ------------------------------------------------------------------------------
 >  Line Number Statements:
 >   Extended opcode 2: set Address to 0x45c880
 >   Advance Line by 25 to 26
 >   Copy
 > ------------------------------------------------------------------------------
 > as the only part of .debug_line which GDB needs for DW_TAG_partial_unit is:
 > ------------------------------------------------------------------------------
 >  The Directory Table:
 >   ../../gdb
 >   /usr/include/bits
 > [...]
 >  The File Name Table:
 >   Entry Dir     Time    Size    Name
 >   1     1       0       0       gdb.c
 >   2     2       0       0       string3.h
 > [...]
 > ------------------------------------------------------------------------------
 > specifically referenced in GDB for DW_AT_decl_file at a single place:
 > ------------------------------------------------------------------------------
 >               fe = &cu->line_header->file_names[file_index - 1];
 >               SYMBOL_SYMTAB (sym) = fe->symtab;
 > ------------------------------------------------------------------------------
 > 
 > This is because for some reason DW_TAG_partial_unit never contains PC-related
 > DWARF information.  I do not know exactly why, the compression ratio is a bit
 > lower due to it but thanksfully currently it is that way:
 > dwz.c:
 > ------------------------------------------------------------------------------
 >         /* These attributes reference code, prevent moving
 >            DIEs with them.  */
 >         case DW_AT_low_pc:
 >         case DW_AT_high_pc:
 >         case DW_AT_entry_pc:
 >         case DW_AT_ranges:
 >           die->die_ck_state = CK_BAD;
 > +
 >   /* State of checksum computation.  Not computed yet, computed and
 >      suitable for moving into partial units, currently being computed
 >      and finally determined unsuitable for moving into partial units.  */
 >   enum { CK_UNKNOWN, CK_KNOWN, CK_BEING_COMPUTED, CK_BAD } die_ck_state : 2;
 > ------------------------------------------------------------------------------
 > I have also verified also real-world Fedora debuginfo files really comply with
 > that assumption with dwgrep
 > 	https://github.com/pmachata/dwgrep
 > using:
 > ------------------------------------------------------------------------------
 > dwgrep -e 'entry ?DW_TAG_partial_unit child* ( ?DW_AT_low_pc , ?DW_AT_high_pc , ?DW_AT_ranges )' /usr/lib/debug/**
 > ------------------------------------------------------------------------------
 > 
 > BTW I think GDB already does not support the whole DW_TAG_imported_unit and
 > DW_TAG_partial_unit usage possibilities as specified by the DWARF standard.
 > I think GDB would not work if DW_TAG_imported_unit was used in some inner
 > level and not at the CU level (readelf -wi level <1>) - this is how DWZ is
 > using DW_TAG_imported_unit.  Therefore I do not think further assumptions
 > about DW_TAG_imported_unit and DW_TAG_partial_unit usage by DWZ are a problem
 > for GDB.
 > 
 > One could save the whole .debug_line decoded PC<->lines mapping (and not just
 > the DW_AT_decl_file table) but:
 >  * there are some problematic corner cases so one could do it incorrectly
 >  * there are no real world data to really test such patch extension
 >  * such extension could be done perfectly incrementally on top of this patch
 > 
 > One could save existing 'struct line_header' in the patch instead of
 > introducing new 'struct dwarf2_line_info'.  The problem is
 > dwarf_decode_line_header() currently uses xmalloc while we need the allocation
 > to be bound to objfile->objfile_obstack.  With 'struct line_header' one would
 > have to make special objfile-time destruction of those 'struct line_header'.
 > 
 > No regressions on {x86_64,x86_64-m32,i686}-fedora21pre-linux-gnu in DWZ mode
 > (contrib/cc-with-tweaks.sh -m, that is dwz -m).  I have seen there are several
 > GDB regressions in non-DWZ -> DWZ mode but that is off-topic for this patch.
 > 
 > 
 > Thanks,
 > Jan
 > 
 > ------------------------------------------------------------------------------
 > 
 > benchmark - on Fedora 20 x86_64 and FSF GDB HEAD:
 > echo -e 'thread apply all bt\nset confirm no\nq'|./gdb -p `pidof soffice.bin` -ex 'set pagination off' -ex 'maintenance set per-command space' -ex 'maintenance set per-command symtab' -ex 'maintenance set per-command time'
 > 
 > FSF GDB HEAD ("thread apply all bt"):
 > Command execution time: 333.693000 (cpu), 335.587539 (wall)
 >                                           ---sec
 > Space used: 1736404992 (+1477189632 for this command)
 >                          ----MB
 > #symtabs: 6838113 (+6809597), #primary symtabs: 3666 (+3655), #blocks: 22968 (+22943)
 > vs.
 > THIS PATCH ("thread apply all bt"):
 > Command execution time: 2.595000 (cpu), 2.607573 (wall)
 >                                         -sec
 > Space used: 340058112 (+85917696 for this command)
 >                         --MB
 > #symtabs: 42221 (+39041), #primary symtabs: 3666 (+3655), #blocks: 22968 (+22943)
 > 
 > FSF GDB HEAD ("thread apply all bt full"):
 > Command execution time: 466.751000 (cpu), 468.345837 (wall)
 >                                           ---sec
 > Space used: 2330132480 (+2070974464 for this command)
 >                          ----MB
 > #symtabs: 9586991 (+9558475), #primary symtabs: 5367 (+5356), #blocks: 31638 (+31613)
 > vs.
 > THIS PATCH ("thread apply all bt full"):
 > Command execution time: 18.907000 (cpu), 18.964125 (wall)
 >                                          --sec
 > Space used: 364462080 (+110325760 for this command)
 >                         ---MB
 > #symtabs: 58780 (+55600), #primary symtabs: 5367 (+5356), #blocks: 31638 (+31613)
 > gdb/
 > 2014-10-01  Jan Kratochvil  <jan.kratochvil@redhat.com>
 > 
 > 	Fix 100x slowdown regression on DWZ files.
 > 	* dwarf2read.c (struct dwarf2_per_objfile): Add lineinfo_hash.
 > 	(struct dwarf2_lineinfo, dwarf2_lineinfo_hash, dwarf2_lineinfo_eq): New.
 > 	(struct dwarf2_cu): Add lineinfo.
 > 	(handle_DW_AT_stmt_list): Use dwarf2_per_objfile->lineinfo_hash, set
 > 	cu->lineinfo.
 > 	(new_symbol_full): Use cu->lineinfo.

Looks like dwz support is going through some of the pains I went through
with type units. :-)

I tested this patch with --target_board=dwarf4-gdb-index
and got a failure in m-static.exp:

info variable everywhere^M
All variables matching regular expression "everywhere":^M
^M
File :^M
const int gnu_obj_4::everywhere;^M
(gdb) FAIL: gdb.cp/m-static.exp: info variable everywhere

Type units read the line table in a separate path,
and when we get here in new_symbol_full:

          if (cu->lineinfo == NULL
              || file_index > cu->lineinfo->file_to_symtab_count)
            complaint (&symfile_complaints,
                       _("file index out of range"));

cu->lineinfo is NULL.

I wouldn't suggest trying too hard for type units and dwz support
to share code, but I think there is room for at least some
exploration. There's also room for some improvement in the type unit
support so if that happens that'd be great (though such improvement
is obviously *not* a requirement for this patch).

OTOH, I do want to avoid any confusion that this patch may inadvertently
introduce. For example, IIUC with your patch as is,
if we read a partial_unit first, before a compile_unit
that has the same stmt_list value, we'll do more processing in
dwarf_decode_lines than we really need to since we only need a file
number to symtab mapping. And if we later read in a compile_unit
with the same stmt_value we'll call dwarf_decode_lines again,
and this time we need the pc/line mapping it computes.
Whereas if we process these in the opposite order we'll only call
dwarf_decode_lines once. I'm sure this will be confusing at first
to some later developer going through this code.
[I could be missing something of course, and I'm happy for any corrections.]

The code that processes stmt_list for type_units is in setup_type_unit_groups.
Note that this code goes to the trouble of re-initializing the buildsym
machinery (see the calls to restart_symtab in dwarf2read.c) when we process
the second and subsequent type units that share a stmt_list value.
This is something that used to be done before your patch and will no
longer be done with your patch (since if we get a cache hit we exit).
It may be that the type_unit support is doing this unnecessarily,
which would be great because we can then simplify it.
The details have dropped out of cache so I'd have to go back and check
why it was done this way.

Further minor comments inline.

 > 
 > diff --git a/gdb/dwarf2read.c b/gdb/dwarf2read.c
 > index 9d0ee13..b24c133 100644
 > --- a/gdb/dwarf2read.c
 > +++ b/gdb/dwarf2read.c
 > @@ -309,8 +309,51 @@ struct dwarf2_per_objfile
 >  
 >    /* The CUs we recently read.  */
 >    VEC (dwarf2_per_cu_ptr) *just_read_cus;
 > +
 > +  /* Table containing struct dwarf2_lineinfo.  */
 > +  htab_t lineinfo_hash;
 > +};
 > +
 > +/* Table mapping .debug_line offsets to any symtab where they are
 > +   instantiated.  */
 > +
 > +struct dwarf2_lineinfo
 > +{
 > +  /* Offset of line number information in .debug_line section.  */
 > +  sect_offset offset;
 > +  unsigned offset_in_dwz : 1;

IWBN to document why offset_in_dwz is here.
It's not obvious why it's needed.

 > +
 > +  /* Number of entries in file_to_symtab array.  */
 > +  unsigned file_to_symtab_count;
 > +
 > +  /* struct is sized to contain FILE_TO_SYMTAB_COUNT elements of this array.
 > +     Map each DW_AT_decl_file entry to any instantiation of matching symtab.
 > +     This array is numbered from zero, DW_AT_decl_file is numbered from one.  */
 > +  struct symtab *file_to_symtab[1];
 >  };
 >  
 > +/* Hash function for a dwarf2_lineinfo.  */
 > +
 > +static hashval_t
 > +dwarf2_lineinfo_hash (const void *item)
 > +{
 > +  const struct dwarf2_lineinfo *ofs = item;
 > +
 > +  return ofs->offset.sect_off ^ ofs->offset_in_dwz;
 > +}
 > +
 > +/* Equality function for a dwarf2_lineinfo.  */
 > +
 > +static int
 > +dwarf2_lineinfo_eq (const void *item_lhs, const void *item_rhs)
 > +{
 > +  const struct dwarf2_lineinfo *ofs_lhs = item_lhs;
 > +  const struct dwarf2_lineinfo *ofs_rhs = item_rhs;
 > +
 > +  return (ofs_lhs->offset.sect_off == ofs_rhs->offset.sect_off
 > +	  && ofs_lhs->offset_in_dwz == ofs_rhs->offset_in_dwz);
 > +}
 > +
 >  static struct dwarf2_per_objfile *dwarf2_per_objfile;
 >  
 >  /* Default names of the debugging sections.  */
 > @@ -489,6 +532,10 @@ struct dwarf2_cu
 >    /* Header data from the line table, during full symbol processing.  */
 >    struct line_header *line_header;
 >  
 > +  /* Table mapping .debug_line offsets to any symtab where they are
 > +     instantiated.  It contains subset of LINE_HEADER information.  */
 > +  struct dwarf2_lineinfo *lineinfo;
 > +
 >    /* A list of methods which need to have physnames computed
 >       after all type information has been read.  */
 >    VEC (delayed_method_info) *method_list;
 > @@ -8975,24 +9022,61 @@ static void
 >  handle_DW_AT_stmt_list (struct die_info *die, struct dwarf2_cu *cu,
 >  			const char *comp_dir, CORE_ADDR lowpc) /* ARI: editCase function */
 >  {
 > +  struct objfile *objfile = dwarf2_per_objfile->objfile;
 >    struct attribute *attr;
 > +  unsigned int line_offset;
 > +  struct dwarf2_lineinfo lineinfo;
 > +  struct line_header *line_header;
 > +  unsigned u;
 > +  void **slot;
 >  
 >    gdb_assert (! cu->per_cu->is_debug_types);
 >  
 >    attr = dwarf2_attr (die, DW_AT_stmt_list, cu);
 > -  if (attr)
 > +  if (attr == NULL)
 > +    return;
 > +
 > +  line_offset = DW_UNSND (attr);
 > +
 > +  if (dwarf2_per_objfile->lineinfo_hash == NULL)
 >      {
 > -      unsigned int line_offset = DW_UNSND (attr);
 > -      struct line_header *line_header
 > -	= dwarf_decode_line_header (line_offset, cu);
 > +      dwarf2_per_objfile->lineinfo_hash =

As much as I prefer "=" going here, convention says to put it on the
next line.

 > +	htab_create_alloc_ex (127, dwarf2_lineinfo_hash, dwarf2_lineinfo_eq,

I don't have any data, but 127 seems high.
I wouldn't change it, I just wanted to ask if you have any data
guiding this choice.
[I'm not worried about spending a bit of extra space on small programs, btw.]

 > +			      NULL, &objfile->objfile_obstack,
 > +			      hashtab_obstack_allocate,
 > +			      dummy_obstack_deallocate);
 > +    }
 >  
 > -      if (line_header)
 > -	{
 > -	  cu->line_header = line_header;
 > -	  make_cleanup (free_cu_line_header, cu);
 > -	  dwarf_decode_lines (line_header, comp_dir, cu, NULL, lowpc);
 > -	}
 > +  lineinfo.offset.sect_off = line_offset;
 > +  lineinfo.offset_in_dwz = cu->per_cu->is_dwz;
 > +  slot = htab_find_slot (dwarf2_per_objfile->lineinfo_hash, &lineinfo, INSERT);
 > +
 > +  /* For DW_TAG_compile_unit we need info like symtab::linetable which
 > +     is not present in *SLOT.  */
 > +  if (die->tag == DW_TAG_partial_unit && *slot != NULL)
 > +    {
 > +      cu->lineinfo = *slot;
 > +      return;
 >      }
 > +
 > +  line_header = dwarf_decode_line_header (line_offset, cu);
 > +  if (line_header == NULL)
 > +    return;
 > +  cu->line_header = line_header;
 > +  make_cleanup (free_cu_line_header, cu);
 > +  dwarf_decode_lines (line_header, comp_dir, cu, NULL, lowpc);
 > +
 > +  cu->lineinfo = obstack_alloc (&objfile->objfile_obstack,
 > +				(sizeof (*cu->lineinfo)
 > +				 + (sizeof (*cu->lineinfo->file_to_symtab)
 > +				    * (line_header->num_file_names - 1))));
 > +  cu->lineinfo->offset.sect_off = line_offset;
 > +  cu->lineinfo->offset_in_dwz = cu->per_cu->is_dwz;
 > +  cu->lineinfo->file_to_symtab_count = line_header->num_file_names;
 > +  for (u = 0; u < cu->lineinfo->file_to_symtab_count; u++)
 > +    cu->lineinfo->file_to_symtab[u] = line_header->file_names[u].symtab;
 > +  if (*slot == NULL)
 > +    *slot = cu->lineinfo;
 >  }
 >  
 >  /* Process DW_TAG_compile_unit or DW_TAG_partial_unit.  */
 > @@ -17870,17 +17954,12 @@ new_symbol_full (struct die_info *die, struct type *type, struct dwarf2_cu *cu,
 >  	{
 >  	  int file_index = DW_UNSND (attr);
 >  
 > -	  if (cu->line_header == NULL
 > -	      || file_index > cu->line_header->num_file_names)
 > +	  if (cu->lineinfo == NULL
 > +	      || file_index > cu->lineinfo->file_to_symtab_count)
 >  	    complaint (&symfile_complaints,
 >  		       _("file index out of range"));
 >  	  else if (file_index > 0)
 > -	    {
 > -	      struct file_entry *fe;
 > -
 > -	      fe = &cu->line_header->file_names[file_index - 1];
 > -	      SYMBOL_SYMTAB (sym) = fe->symtab;
 > -	    }
 > +	    SYMBOL_SYMTAB (sym) = cu->lineinfo->file_to_symtab[file_index - 1];
 >  	}
 >  
 >        switch (die->tag)