[DWARF] Remove a couple of log statements

[zturner]

Summary

I don't find these specific log statements particularly high value, as they appear more just like simple function tracing calls (i.e. they log low level implementation details, not high level program flow) so I'm removing them from the low level DWARF parsing libraries.

I'm prepared to be convinced that we actually should do something other than outright delete them, but I did look at each one specifically as well as the surrounding context before deciding that they were probably ok to delete.

My reasoning for deleting these is that they are all on the success codepath and have a very limited number of call-sites (in most cases actually just 1), so in most cases a previous log statement would necessarily be followed by the deleted log statement, so therefore it doesn't actually add much (if any) diagnostic value.

[clayborg]

Most of these logs seem useful. See inline comments.

lldb/source/Plugins/SymbolFile/DWARF/DWARFDebugAranges.cpp

121–144 ↗

(On Diff #191118)

These two seem useful. They are only when logging .debug_aranges with DWARF_LOG_DEBUG_ARANGES. What is left if we remove this?

lldb/source/Plugins/SymbolFile/DWARF/DWARFDebugInfo.cpp

93 ↗

(On Diff #191118)

All above logs seem useful. Sometimes we don't get a .debug_aranges section which means we must parse the address ranges manually. When we are logging .debug_aranges, it is handy to know where the info came from (.debug_aranges, or manual index).

lldb/source/Plugins/SymbolFile/DWARF/DWARFUnit.cpp

168–176 ↗

(On Diff #191118)

It is nice to know when we parse all DIEs for a compile unit. This helps us to verify that our lazy DWARF parsing is working. When we have good accelerator tables, like the Apple ones or DWARF 5 ones, then we will only parse the DIEs in a compile unit when we need to. Seems like we need one when it starts and one when it ends so we could see timestamp times...

837–844 ↗

(On Diff #191118)

This seems useful as it tells us when we manually index a compile unit for all function address ranges which can be expensive.

[zturner]

In all cases, I think the question worth asking is not "could it be used for X", but rather "how often is it actually used for X". Otherwise, it's just technical debt IMO. There's a lot of things that are possible in theory, but unless it exhibits value in practice, YAGNI.

lldb/source/Plugins/SymbolFile/DWARF/DWARFDebugAranges.cpp

121–144 ↗

(On Diff #191118)

What useful information does it tell you though? That the function was called? That's the part that doesn't seem useful. It gives you some information about bytes saved and entries combined, which could arguably be useful, but are you aware of any situations where anyone actually looked at this log statement? One option is moving it up to a higher level if so, but I think it's worth seriously asking why you would want to know this, and if you did want to know it, why running LLDB in a debugger and/or adding some temporary logging to diagnose a specific problem wouldn't be sufficient.

lldb/source/Plugins/SymbolFile/DWARF/DWARFDebugInfo.cpp

93 ↗

(On Diff #191118)

In that case, we can move the log up to a much higher level, and print one log all the way up in SymbolFileDWARF that says "aranges not present, using range info from manual index". It doesn't need to be in the low level parsing code

lldb/source/Plugins/SymbolFile/DWARF/DWARFUnit.cpp

168–176 ↗

(On Diff #191118)

This function already has this at the beginning:

static Timer::Category func_cat(LLVM_PRETTY_FUNCTION);
  static Timer::Category func_cat(LLVM_PRETTY_FUNCTION);
  Timer scoped_timer(func_cat, "%8.8x: DWARFUnit::ExtractDIEsIfNeeded()", m_offset);

if timing information is needed. There are also other options, like running a profiler or function tracer. For verifying that the lazy parsing is working, we should just have tests, not log statements that require someone to manually inspect.

837–844 ↗

(On Diff #191118)

This information could be stored at a higher level, it doesn't have to be here.

[JDevlieghere]

In D59498#1433421, @zturner wrote:

In all cases, I think the question worth asking is not "could it be used for X", but rather "how often is it actually used for X". Otherwise, it's just technical debt IMO. There's a lot of things that are possible in theory, but unless it exhibits value in practice, YAGNI.

I strongly agree with this. Unless this is something we want to know from a user, we can probably get this information by setting a breakpoint.

This is bad advertising. It's like a butcher that sells vegan meat. (Quote @davide)

[clayborg]

I haven't used it in a long time. I can add it back temporarily if I ever need to.

source/Plugins/SymbolFile/DWARF/DWARFDebugAranges.cpp

 //===-- DWARFDebugAranges.cpp -----------------------------------*- C++ -*-===//
 //
 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 // See https://llvm.org/LICENSE.txt for license information.
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 
 #include "DWARFDebugAranges.h"
 
 #include <assert.h>
 #include <stdio.h>
 
 #include <algorithm>
 
-#include "lldb/Utility/Log.h"
 #include "lldb/Utility/Stream.h"
 #include "lldb/Utility/Timer.h"
 
 #include "DWARFUnit.h"
 #include "DWARFDebugInfo.h"
-#include "LogChannelDWARF.h"
 #include "SymbolFileDWARF.h"
 
 using namespace lldb;
 using namespace lldb_private;
 
 //----------------------------------------------------------------------
 // Constructor
 //----------------------------------------------------------------------
if (high_pc > low_pc)
     m_aranges.Append(RangeToDIE::Entry(low_pc, high_pc - low_pc, offset));
 }
 
 void DWARFDebugAranges::Sort(bool minimize) {
   static Timer::Category func_cat(LLVM_PRETTY_FUNCTION);
   Timer scoped_timer(func_cat, "%s this = %p", LLVM_PRETTY_FUNCTION,
                      static_cast<void *>(this));
 
-  Log *log(LogChannelDWARF::GetLogIfAll(DWARF_LOG_DEBUG_ARANGES));
-  size_t orig_arange_size = 0;
-  if (log) {
-    orig_arange_size = m_aranges.GetSize();
-    log->Printf("DWARFDebugAranges::Sort(minimize = %u) with %" PRIu64
-                " entries",
-                minimize, (uint64_t)orig_arange_size);
-  }
-
   m_aranges.Sort();
   m_aranges.CombineConsecutiveEntriesWithEqualData();
-
-  if (log) {
-    if (minimize) {
-      const size_t new_arange_size = m_aranges.GetSize();
-      const size_t delta = orig_arange_size - new_arange_size;
-      log->Printf("DWARFDebugAranges::Sort() %" PRIu64
-                  " entries after minimizing (%" PRIu64
-                  " entries combined for %" PRIu64 " bytes saved)",
-                  (uint64_t)new_arange_size, (uint64_t)delta,
-                  (uint64_t)delta * sizeof(Range));
-    }
-    Dump(log);
-  }
 }
 
 //----------------------------------------------------------------------
 // FindAddress
 //----------------------------------------------------------------------
 dw_offset_t DWARFDebugAranges::FindAddress(dw_addr_t address) const {
   const RangeToDIE::Entry *entry = m_aranges.FindEntryThatContains(address);
   if (entry)
     return entry->data;
   return DW_INVALID_OFFSET;
 }

source/Plugins/SymbolFile/DWARF/DWARFDebugInfo.cpp

 #include "lldb/Utility/Stream.h"
 
 #include "DWARFCompileUnit.h"
 #include "DWARFDebugAranges.h"
 #include "DWARFDebugAranges.h"
 #include "DWARFDebugInfo.h"
 #include "DWARFDebugInfoEntry.h"
 #include "DWARFFormValue.h"
-#include "LogChannelDWARF.h"
 
 using namespace lldb;
 using namespace lldb_private;
 using namespace std;
 
 //----------------------------------------------------------------------
 // Constructor
 //----------------------------------------------------------------------

 }
 
 llvm::Expected<DWARFDebugAranges &> DWARFDebugInfo::GetCompileUnitAranges() {
   if (m_cu_aranges_up)
     return *m_cu_aranges_up;
 
   assert(m_dwarf2Data);
 
-  Log *log(LogChannelDWARF::GetLogIfAll(DWARF_LOG_DEBUG_ARANGES));
-
   m_cu_aranges_up = llvm::make_unique<DWARFDebugAranges>();
   const DWARFDataExtractor &debug_aranges_data =
       m_dwarf2Data->get_debug_aranges_data();
   if (debug_aranges_data.GetByteSize() > 0) {
-    if (log)
-      log->Printf(
-          "DWARFDebugInfo::GetCompileUnitAranges() for \"%s\" from "
-          ".debug_aranges",
-          m_dwarf2Data->GetObjectFile()->GetFileSpec().GetPath().c_str());
     llvm::Error error = m_cu_aranges_up->extract(debug_aranges_data);
     if (error)
       return std::move(error);
   }
 
   // Make a list of all CUs represented by the arange data in the file.
   std::set<dw_offset_t> cus_with_data;
   for (size_t n = 0; n < m_cu_aranges_up->GetNumRanges(); n++) {
     dw_offset_t offset = m_cu_aranges_up->OffsetAtIndex(n);
     if (offset != DW_INVALID_OFFSET)
       cus_with_data.insert(offset);
   }
 
   // Manually build arange data for everything that wasn't in the
   // .debug_aranges table.
-  bool printed = false;
   const size_t num_compile_units = GetNumCompileUnits();
   for (size_t idx = 0; idx < num_compile_units; ++idx) {
     DWARFUnit *cu = GetCompileUnitAtIndex(idx);
 
     dw_offset_t offset = cu->GetOffset();
-    if (cus_with_data.find(offset) == cus_with_data.end()) {
-      if (log) {
-        if (!printed)
-          log->Printf(
-              "DWARFDebugInfo::GetCompileUnitAranges() for \"%s\" by parsing",
-              m_dwarf2Data->GetObjectFile()->GetFileSpec().GetPath().c_str());
-        printed = true;
-      }
+    if (cus_with_data.find(offset) == cus_with_data.end())
       cu->BuildAddressRangeTable(m_dwarf2Data, m_cu_aranges_up.get());
-    }
-  }
 
   const bool minimize = true;
   m_cu_aranges_up->Sort(minimize);
   return *m_cu_aranges_up;
 }
 
 void DWARFDebugInfo::ParseCompileUnitHeadersIfNeeded() {
   if (!m_compile_units.empty())

source/Plugins/SymbolFile/DWARF/DWARFUnit.cpp

void DWARFUnit::ExtractDIEsRWLocked() {
 
   // Set the offset to that of the first DIE and calculate the start of the
   // next compilation unit header.
   lldb::offset_t offset = GetFirstDIEOffset();
   lldb::offset_t next_cu_offset = GetNextCompileUnitOffset();
 
   DWARFDebugInfoEntry die;
   // Keep a flat array of the DIE for binary lookup by DIE offset
-  Log *log(
-      LogChannelDWARF::GetLogIfAny(DWARF_LOG_DEBUG_INFO | DWARF_LOG_LOOKUPS));
-  if (log) {
-    m_dwarf->GetObjectFile()->GetModule()->LogMessageVerboseBacktrace(
-        log,
-        "DWARFUnit::ExtractDIEsIfNeeded () for compile unit at "
-        ".debug_info[0x%8.8x]",
-        GetOffset());
-  }
 
   uint32_t depth = 0;
   // We are in our compile unit, parse starting at the offset we were told to
   // parse
   const DWARFDataExtractor &data = GetData();
   std::vector<uint32_t> die_index_stack;
   die_index_stack.reserve(32);
   die_index_stack.push_back(0);
SymbolFileDWARFDwo *DWARFUnit::GetDwoSymbolFile() const {
   return m_dwo_symbol_file.get();
 }
 
 dw_offset_t DWARFUnit::GetBaseObjOffset() const { return m_base_obj_offset; }
 
 const DWARFDebugAranges &DWARFUnit::GetFunctionAranges() {
   if (m_func_aranges_up == NULL) {
     m_func_aranges_up.reset(new DWARFDebugAranges());
-    Log *log(LogChannelDWARF::GetLogIfAll(DWARF_LOG_DEBUG_ARANGES));
-
-    if (log) {
-      m_dwarf->GetObjectFile()->GetModule()->LogMessage(
-          log,
-          "DWARFUnit::GetFunctionAranges() for compile unit at "
-          ".debug_info[0x%8.8x]",
-          GetOffset());
-    }
     const DWARFDebugInfoEntry *die = DIEPtr();
     if (die)
       die->BuildFunctionAddressRangeTable(m_dwarf, this,
                                           m_func_aranges_up.get());
 
     if (m_dwo_symbol_file) {
       DWARFUnit *dwo_cu = m_dwo_symbol_file->GetCompileUnit();
       const DWARFDebugInfoEntry *dwo_die = dwo_cu->DIEPtr();