Speedup llvm-dwarfdump 3.9x

[jankratochvil]

Summary

Currently strace llvm-dwarfdump x.debug >/tmp/file:

ioctl(1, TCGETS, 0x7ffd64d7f340)        = -1 ENOTTY (Inappropriate ioctl for device)
write(1, "           DW_AT_decl_line\t(89)\n"..., 4096) = 4096
ioctl(1, TCGETS, 0x7ffd64d7f400)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(1, TCGETS, 0x7ffd64d7f410)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(1, TCGETS, 0x7ffd64d7f400)        = -1 ENOTTY (Inappropriate ioctl for device)

After this patch:

write(1, "0000000000001102 \"strlen\")\n     "..., 4096) = 4096
write(1, "site\n                  DW_AT_low"..., 4096) = 4096
write(1, "d53)\n\n0x000e4d4d:       DW_TAG_G"..., 4096) = 4096

The same speedup can be achieved by --color=0 but that is not much convenient.
After this patch it still uses ioctl for printing DWARF parsing errors.
Maybe raw_ostream &OS could be moved into DIDumpOptions DumpOpts which would somehow make this patch more simple, I can investigate it more and change it upon request.
I can also drop this patch if it looks too hacky.

[jhenderson]

Thanks for bringing this up!

I believe llvm-dwarfdump isn't the only thing that prints using colours. I think we need a more general solution than this.

Also, perhaps this should be done by the stream itself - it seems like the stream knows whether or not it supports colours, so should we not just have the stream ignore attempts to use colours if the underlying thing doesn't support them?

[jankratochvil]

In D86406#2232912, @jhenderson wrote:

Also, perhaps this should be done by the stream itself - it seems like the stream knows whether or not it supports colours, so should we not just have the stream ignore attempts to use colours if the underlying thing doesn't support them?

OK, I agree, I will move it there. That should also solve the caching problem.

[JDevlieghere]

If I understand the patch correctly, the speedup is gained by caching the mode instead of trying to recompute it every time we call colorsEnabled()? This seems like a huge speedup for such a small thing, maybe I'm missing something?

In D86406#2232912, @jhenderson wrote:

Also, perhaps this should be done by the stream itself - it seems like the stream knows whether or not it supports colours, so should we not just have the stream ignore attempts to use colours if the underlying thing doesn't support them?

We already disable colors when they're not supported by the stream.

In D86406#2232918, @jankratochvil wrote:

OK, I agree, I will move it there. That should also solve the caching problem.

I don't think we should move it into the stream, if that's what you mean by "there". The color cl::opt is part of WithColor so we should check its value there.

Can we achieve the same thing by resolving the ColorMode to Enable and Disable in the WihtColor constructor?

[jhenderson]

In D86406#2234381, @JDevlieghere wrote:

If I understand the patch correctly, the speedup is gained by caching the mode instead of trying to recompute it every time we call colorsEnabled()? This seems like a huge speedup for such a small thing, maybe I'm missing something?

In D86406#2232912, @jhenderson wrote:

Also, perhaps this should be done by the stream itself - it seems like the stream knows whether or not it supports colours, so should we not just have the stream ignore attempts to use colours if the underlying thing doesn't support them?

We already disable colors when they're not supported by the stream.

Maybe I misunderstood what this bit of the strace output was complaining about then:
ioctl(1, TCGETS, 0x7ffd64d7f340) = -1 ENOTTY (Inappropriate ioctl for device)
(I have never used strace, so was only guessing based on its general appearance). I took it to mean that an attempt was made to change the colour, but failed because files don't support different colours, and that this failure is expensive.

In D86406#2232918, @jankratochvil wrote:

OK, I agree, I will move it there. That should also solve the caching problem.

I don't think we should move it into the stream, if that's what you mean by "there". The color cl::opt is part of WithColor so we should check its value there.

Can we achieve the same thing by resolving the ColorMode to Enable and Disable in the WihtColor constructor?

[jankratochvil]

In D86406#2234381, @JDevlieghere wrote:

If I understand the patch correctly, the speedup is gained by caching the mode instead of trying to recompute it every time we call colorsEnabled()?

Yes.

This seems like a huge speedup for such a small thing, maybe I'm missing something?

Detecting whether fd 1 supports colors means an ioctl() call which is a kernel call. That is several orders of magnitue more expensive than any in-process codeflow and in-process calculations. This is on Linux, I did not check OSX.

I don't think we should move it into the stream, if that's what you mean by "there". The color cl::opt is part of WithColor so we should check its value there.

I plan to make raw_ostream to have auto/on/off mode (default=auto). WithColor's ctor will set the mode of the raw_ostream. raw_ostream will do the expensive ioctl() detection only during first time changing color if raw_ostream has auto mode and raw_ostream will cache the detected value.

(Not yet written, busy with DWZ stuff, thanks for asking.)

Can we achieve the same thing by resolving the ColorMode to Enable and Disable in the WithColor constructor?

No because WithColor is ctored/dtored many times for every DIE. This is what results in so many expensive ioctl()s.

It could be done in WithColor if its Mode is changed to a static member but then that static member would be set according to current raw_ostream and it would be incorrect if WithColor's static member is later used with different raw_ostream.

In D86406#2235331, @jhenderson wrote:

Maybe I misunderstood what this bit of the strace output was complaining about then:
ioctl(1, TCGETS, 0x7ffd64d7f340) = -1 ENOTTY (Inappropriate ioctl for device)
(I have never used strace, so was only guessing based on its general appearance). I took it to mean that an attempt was made to change the colour, but failed because files don't support different colours, and that this failure is expensive.

Expensive is the detection. Color output is just printing some bytes like "\x1B[0;36m".

[joerg]

Can you change raw_fd_ostream::has_colors to memoize the result of FileDescriptorHasColors(FD) instead? That should give most of the performance gain without breaking the abstractions as much.

[jankratochvil]

In D86406#2235959, @joerg wrote:

Can you change raw_fd_ostream::has_colors to memoize the result of FileDescriptorHasColors(FD) instead?

Done, yes, that looks simple and it works. The new code is not thread-safe but other member variables there also are not.

[joerg]

llvm/include/llvm/Support/raw_ostream.h

298 ↗

(On Diff #287695)

I'd keep the original const in the interface contract and mark HasColors as mutable instead. It's an implementation detail that the field is set lazily and the property itself should be invariant.

[jhenderson]

LGTM, thanks!

llvm/include/llvm/DebugInfo/DIContext.h

struct DIDumpOptions {
   uint8_t AddrSize = 4; // Address byte size to assume when extracting.
   bool ShowAddresses = true;
   bool ShowChildren = false;
   bool ShowParents = false;
   bool ShowForm = false;
   bool SummarizeTypes = false;
   bool Verbose = false;
   bool DisplayRawContents = false;
+  llvm::ColorMode ColorMode = llvm::ColorMode::Auto;
 
   /// Return default option set for printing a single DIE without children.
   static DIDumpOptions getForSingleDIE() {
     DIDumpOptions Opts;
     Opts.ChildRecurseDepth = 0;
     Opts.ParentRecurseDepth = 0;
     return Opts;
   }

llvm/include/llvm/DebugInfo/DWARF/DWARFFormValue.h

public:
   /// \param OffsetPtr A reference to the offset that will be updated.
   /// \param FormParams DWARF parameters to help interpret forms.
   /// \returns true on success, false if the form was not skipped.
   static bool skipValue(dwarf::Form Form, DataExtractor DebugInfoData,
                         uint64_t *OffsetPtr,
                         const dwarf::FormParams FormParams);
 
 private:
-  void dumpString(raw_ostream &OS) const;
+  void dumpString(raw_ostream &OS, const DIDumpOptions &DumpOpts) const;
 };
 
 namespace dwarf {
 
 /// Take an optional DWARFFormValue and try to extract a string value from it.
 ///
 /// \param V and optional DWARFFormValue to attempt to extract the value from.
 /// \returns an optional value that contains a value if the form value

llvm/include/llvm/Support/WithColor.h

public:
 
   /// Implement default handling for Error.
   /// Print "error: " to stderr.
   static void defaultErrorHandler(Error Err);
 
   /// Implement default handling for Warning.
   /// Print "warning: " to stderr.
   static void defaultWarningHandler(Error Warning);
+
+  /// Return ColorMode::Enable or ColorMode::Disable instead of ColorMode::Auto.
+  /// Cache that value for later calls of WithColor constructor.
+  static ColorMode GetModeForOS(raw_ostream &OS);
 };
 
 } // end namespace llvm
 
 #endif // LLVM_LIB_DEBUGINFO_WITHCOLOR_H

llvm/lib/DebugInfo/DWARF/DWARFDie.cpp

static void dumpAttribute(raw_ostream &OS, const DWARFDie &Die,
                           uint64_t *OffsetPtr, dwarf::Attribute Attr,
                           dwarf::Form Form, unsigned Indent,
                           DIDumpOptions DumpOpts) {
   if (!Die.isValid())
     return;
   const char BaseIndent[] = "            ";
   OS << BaseIndent;
   OS.indent(Indent + 2);
-  WithColor(OS, HighlightColor::Attribute) << formatv("{0}", Attr);
+  WithColor(OS, HighlightColor::Attribute, DumpOpts.ColorMode)
+      << formatv("{0}", Attr);
 
   if (DumpOpts.Verbose || DumpOpts.ShowForm)
     OS << formatv(" [{0}]", Form);
 
   DWARFUnit *U = Die.getDwarfUnit();
   DWARFFormValue FormValue = DWARFFormValue::createFromUnit(Form, U, OffsetPtr);
 
   OS << "\t(";
if (const auto *LT = U->getContext().getLineTableForUnit(U))
               DILineInfoSpecifier::FileLineInfoKind::AbsoluteFilePath, File)) {
         File = '"' + File + '"';
         Name = File;
       }
   } else if (Optional<uint64_t> Val = FormValue.getAsUnsignedConstant())
     Name = AttributeValueString(Attr, *Val);
 
   if (!Name.empty())
-    WithColor(OS, Color) << Name;
+    WithColor(OS, Color, DumpOpts.ColorMode) << Name;
   else if (Attr == DW_AT_decl_line || Attr == DW_AT_call_line)
     OS << *FormValue.getAsUnsignedConstant();
   else if (Attr == DW_AT_high_pc && !DumpOpts.ShowForm && !DumpOpts.Verbose &&
            FormValue.getAsUnsignedConstant()) {
     if (DumpOpts.ShowAddresses) {
       // Print the actual address rather than the offset.
       uint64_t LowPC, HighPC, Index;
       if (Die.getLowAndHighPC(LowPC, HighPC, Index))
if (DumpOpts.ShowParents) {
     ParentDumpOpts.ShowParents = false;
     ParentDumpOpts.ShowChildren = false;
     Indent = dumpParentChain(getParent(), OS, Indent, ParentDumpOpts);
   }
 
   if (debug_info_data.isValidOffset(offset)) {
     uint32_t abbrCode = debug_info_data.getULEB128(&offset);
     if (DumpOpts.ShowAddresses)
-      WithColor(OS, HighlightColor::Address).get()
+      WithColor(OS, HighlightColor::Address, DumpOpts.ColorMode).get()
           << format("\n0x%8.8" PRIx64 ": ", Offset);
 
     if (abbrCode) {
       auto AbbrevDecl = getAbbreviationDeclarationPtr();
       if (AbbrevDecl) {
-        WithColor(OS, HighlightColor::Tag).get().indent(Indent)
+        WithColor(OS, HighlightColor::Tag, DumpOpts.ColorMode)
+                .get()
+                .indent(Indent)
             << formatv("{0}", getTag());
         if (DumpOpts.Verbose)
           OS << format(" [%u] %c", abbrCode,
                        AbbrevDecl->hasChildren() ? '*' : ' ');
         OS << '\n';
 
         // Dump all data in the DIE for the attributes.
         for (const auto &AttrSpec : AbbrevDecl->attributes()) {

llvm/lib/DebugInfo/DWARF/DWARFFormValue.cpp

void DWARFFormValue::dumpAddressSection(const DWARFObject &Obj, raw_ostream &OS,
   // Print section index if name is not unique.
   if (!SecRef.IsNameUnique)
     OS << format(" [%" PRIu64 "]", SectionIndex);
 }
 
 void DWARFFormValue::dump(raw_ostream &OS, DIDumpOptions DumpOpts) const {
   uint64_t UValue = Value.uval;
   bool CURelativeOffset = false;
-  raw_ostream &AddrOS = DumpOpts.ShowAddresses
-                            ? WithColor(OS, HighlightColor::Address).get()
-                            : nulls();
+  raw_ostream &AddrOS =
+      DumpOpts.ShowAddresses
+          ? WithColor(OS, HighlightColor::Address, DumpOpts.ColorMode).get()
   int OffsetDumpWidth = 2 * dwarf::getDwarfOffsetByteSize(Format);
   switch (Form) {
   case DW_FORM_addr:
     dumpSectionedAddress(AddrOS, DumpOpts, {Value.uval, Value.SectionIndex});
     break;
   case DW_FORM_addrx:
   case DW_FORM_addrx1:
   case DW_FORM_addrx2:
case DW_FORM_sdata:
     OS << Value.sval;
     break;
   case DW_FORM_udata:
     OS << Value.uval;
     break;
   case DW_FORM_strp:
     if (DumpOpts.Verbose)
       OS << format(" .debug_str[0x%0*" PRIx64 "] = ", OffsetDumpWidth, UValue);
-    dumpString(OS);
+    dumpString(OS, DumpOpts);
     break;
   case DW_FORM_line_strp:
     if (DumpOpts.Verbose)
       OS << format(" .debug_line_str[0x%0*" PRIx64 "] = ", OffsetDumpWidth,
                    UValue);
-    dumpString(OS);
+    dumpString(OS, DumpOpts);
     break;
   case DW_FORM_strx:
   case DW_FORM_strx1:
   case DW_FORM_strx2:
   case DW_FORM_strx3:
   case DW_FORM_strx4:
   case DW_FORM_GNU_str_index:
     if (DumpOpts.Verbose)
       OS << format("indexed (%8.8x) string = ", (uint32_t)UValue);
-    dumpString(OS);
+    dumpString(OS, DumpOpts);
     break;
   case DW_FORM_GNU_strp_alt:
     if (DumpOpts.Verbose)
       OS << format("alt indirect string, offset: 0x%" PRIx64 "", UValue);
-    dumpString(OS);
+    dumpString(OS, DumpOpts);
     break;
   case DW_FORM_ref_addr:
     AddrOS << format("0x%016" PRIx64, UValue);
     break;
   case DW_FORM_ref1:
     CURelativeOffset = true;
     if (DumpOpts.Verbose)
       AddrOS << format("cu + 0x%2.2x", (uint8_t)UValue);
default:
     OS << format("DW_FORM(0x%4.4x)", Form);
     break;
   }
 
   if (CURelativeOffset) {
     if (DumpOpts.Verbose)
       OS << " => {";
     if (DumpOpts.ShowAddresses)
-      WithColor(OS, HighlightColor::Address).get()
+      WithColor(OS, HighlightColor::Address, DumpOpts.ColorMode).get()
           << format("0x%8.8" PRIx64, UValue + (U ? U->getOffset() : 0));
     if (DumpOpts.Verbose)
       OS << "}";
   }
 }
 
-void DWARFFormValue::dumpString(raw_ostream &OS) const {
+void DWARFFormValue::dumpString(raw_ostream &OS,
+                                const DIDumpOptions &DumpOpts) const {
   Optional<const char *> DbgStr = getAsCString();
   if (DbgStr.hasValue()) {
-    auto COS = WithColor(OS, HighlightColor::String);
+    auto COS = WithColor(OS, HighlightColor::String, DumpOpts.ColorMode);
     COS.get() << '"';
     COS.get().write_escaped(DbgStr.getValue());
     COS.get() << '"';
   }
 }
 
 Optional<const char *> DWARFFormValue::getAsCString() const {
   if (!isFormClass(FC_String))

llvm/lib/Support/WithColor.cpp

raw_ostream &WithColor::remark(raw_ostream &OS, StringRef Prefix,
   if (!Prefix.empty())
     OS << Prefix << ": ";
   return WithColor(OS, HighlightColor::Remark,
                    DisableColors ? ColorMode::Disable : ColorMode::Auto)
              .get()
          << "remark: ";
 }
 
+ColorMode WithColor::GetModeForOS(raw_ostream &OS) {
+  return (UseColor == cl::BOU_UNSET ? OS.has_colors()
+                                    : UseColor == cl::BOU_TRUE)
+             ? ColorMode::Enable
+             : ColorMode::Disable;
+}
+
 bool WithColor::colorsEnabled() {
   switch (Mode) {
   case ColorMode::Enable:
     return true;
   case ColorMode::Disable:
     return false;
   case ColorMode::Auto:
-    return UseColor == cl::BOU_UNSET ? OS.has_colors()
-                                     : UseColor == cl::BOU_TRUE;
+    Mode = GetModeForOS(OS);
+    return colorsEnabled();
   }
   llvm_unreachable("All cases handled above.");
 }
 
 WithColor &WithColor::changeColor(raw_ostream::Colors Color, bool Bold,
                                   bool BG) {
   if (colorsEnabled())
     OS.changeColor(Color, Bold, BG);

llvm/tools/llvm-dwarfdump/llvm-dwarfdump.cpp

 
 static void error(StringRef Prefix, std::error_code EC) {
   if (!EC)
     return;
   WithColor::error() << Prefix << ": " << EC.message() << "\n";
   exit(1);
 }
 
-static DIDumpOptions getDumpOpts(DWARFContext &C) {
+static DIDumpOptions getDumpOpts(DWARFContext &C, raw_ostream &OS) {
   DIDumpOptions DumpOpts;
   DumpOpts.DumpType = DumpType;
   DumpOpts.ChildRecurseDepth = ChildRecurseDepth;
   DumpOpts.ParentRecurseDepth = ParentRecurseDepth;
   DumpOpts.ShowAddresses = !Diff;
   DumpOpts.ShowChildren = ShowChildren;
   DumpOpts.ShowParents = ShowParents;
   DumpOpts.ShowForm = ShowForm;
   DumpOpts.SummarizeTypes = SummarizeTypes;
   DumpOpts.Verbose = Verbose;
+  DumpOpts.ColorMode = llvm::WithColor::GetModeForOS(OS);
   DumpOpts.RecoverableErrorHandler = C.getRecoverableErrorHandler();
   // In -verify mode, print DIEs without children in error messages.
   if (Verify)
     return DumpOpts.noImplicitRecursion();
   return DumpOpts;
 }
 
 static uint32_t getCPUType(MachOObjectFile &MachO) {

 }
 
 using HandlerFn = std::function<bool(ObjectFile &, DWARFContext &DICtx,
                                      const Twine &, raw_ostream &)>;
 
 /// Print only DIEs that have a certain name.
 static bool filterByName(const StringSet<> &Names, DWARFDie Die,
                          StringRef NameRef, raw_ostream &OS) {
-  DIDumpOptions DumpOpts = getDumpOpts(Die.getDwarfUnit()->getContext());
+  DIDumpOptions DumpOpts = getDumpOpts(Die.getDwarfUnit()->getContext(), OS);
   std::string Name =
       (IgnoreCase && !UseRegex) ? NameRef.lower() : NameRef.str();
   if (UseRegex) {
     // Match regular expression.
     for (auto Pattern : Names.keys()) {
       Regex RE(Pattern, IgnoreCase ? Regex::IgnoreCase : Regex::NoFlags);
       std::string Error;
       if (!RE.isValid(Error)) {
for (const auto &Name : Names) {
     getDies(DICtx, DICtx.getAppleNames(), Name, Dies);
     getDies(DICtx, DICtx.getAppleTypes(), Name, Dies);
     getDies(DICtx, DICtx.getAppleNamespaces(), Name, Dies);
     getDies(DICtx, DICtx.getDebugNames(), Name, Dies);
   }
   llvm::sort(Dies);
   Dies.erase(std::unique(Dies.begin(), Dies.end()), Dies.end());
 
-  DIDumpOptions DumpOpts = getDumpOpts(DICtx);
+  DIDumpOptions DumpOpts = getDumpOpts(DICtx, OS);
   for (DWARFDie Die : Dies)
     Die.dump(OS, 0, DumpOpts);
 }
 
 /// Handle the --lookup option and dump the DIEs and line info for the given
 /// address.
 /// TODO: specified Address for --lookup option could relate for several
 /// different sections(in case not-linked object file). llvm-dwarfdump
 /// need to do something with this: extend lookup option with section
 /// information or probably display all matched entries, or something else...
 static bool lookup(ObjectFile &Obj, DWARFContext &DICtx, uint64_t Address,
                    raw_ostream &OS) {
   auto DIEsForAddr = DICtx.getDIEsForAddress(Lookup);
 
   if (!DIEsForAddr)
     return false;
 
-  DIDumpOptions DumpOpts = getDumpOpts(DICtx);
+  DIDumpOptions DumpOpts = getDumpOpts(DICtx, OS);
   DumpOpts.ChildRecurseDepth = 0;
   DIEsForAddr.CompileUnit->dump(OS, DumpOpts);
   if (DIEsForAddr.FunctionDIE) {
     DIEsForAddr.FunctionDIE.dump(OS, 2, DumpOpts);
     if (DIEsForAddr.BlockDIE)
       DIEsForAddr.BlockDIE.dump(OS, 4, DumpOpts);
   }
 
static bool dumpObjectFile(ObjectFile &Obj, DWARFContext &DICtx,
 
   // Handle the --find option and lower it to --debug-info=<offset>.
   if (!Find.empty()) {
     filterByAccelName(Find, DICtx, OS);
     return true;
   }
 
   // Dump the complete DWARF structure.
-  DICtx.dump(OS, getDumpOpts(DICtx), DumpOffsets);
+  DICtx.dump(OS, getDumpOpts(DICtx, OS), DumpOffsets);
   return true;
 }
 
 static bool verifyObjectFile(ObjectFile &Obj, DWARFContext &DICtx,
                              const Twine &Filename, raw_ostream &OS) {
   // Verify the DWARF and exit with non-zero exit status if verification
   // fails.
   raw_ostream &stream = Quiet ? nulls() : OS;
   stream << "Verifying " << Filename.str() << ":\tfile format "
   << Obj.getFileFormatName() << "\n";
-  bool Result = DICtx.verify(stream, getDumpOpts(DICtx));
+  bool Result = DICtx.verify(stream, getDumpOpts(DICtx, OS));
   if (Result)
     stream << "No errors.\n";
   else
     stream << "Errors detected.\n";
   return Result;
 }
 
 static bool handleBuffer(StringRef Filename, MemoryBufferRef Buffer,