[DebugInfo] Improve new line printing in debug line verbose output

[jhenderson]

Summary

The new line printing for debug line verbose output was inconsistent. For new rows in the matrix, a blank line followed, whilst the DW_LNS_copy opcode actually resulted in two blank lines. There was also potential inconsistency in the blank lines at the end of the table. This patch mostly resolves these issues - no blank lines should appear in the output except for a single line after the prologue and at table end to separate it from any subsquent table, plus some instances after error messages.

Also add a unit test for verbose output to test the fine details of new line placement and other aspects of verbose output.

Depends on D80989.
Also depends on D80797.

[dblaikie]

llvm/lib/DebugInfo/DWARF/DWARFDebugLine.cpp

714–717

This is the sort of "let's try to curate where errors print out relative to output" changes/direction I think are pretty unfortunate - being able to return errors rather than passing in error handlers seems like a better general coding paradigm where possible (while the callback system for warnings is great, and callbacks for errors are sometimes necessary - when there is some ability to print an error and continue) - returning errors seems clearer/more obvious/simpler control flow (there's no ability to accidentally print an error and continue because you forgot the error handler doesn't terminate execution/need to separately return? and what value do you return if you need to communicate to the caller they need to stop too etc)...

1073

Could you snapshot the length of the matrix before and after, and test if they're different rather than having to add a second operation next to every appendToMatrix? That would seem less error-prone (less possible to miss the pairing, have the two lines diverge in any way, etc)?

[jhenderson]

llvm/lib/DebugInfo/DWARF/DWARFDebugLine.cpp

714–717

The problem is that in the common case, most tools are doing the same thing with both recoverable and unrecoverable errors, it's just done at different times. This means that some error messages appear in the middle of parsing the table (before the terminating blank line), whilst others appear after the prologue has been printed, after the blank line, and seemingly with the next table. This is the incosistency and potential confusion I'm trying to avoid here.

I have a patch for this already, but essentially all that it does is change this function to return void, having passed the error to a separate UnrecoverableErrorHandler (which already exists in higher-level code). The change is NFC from the point of view of what gets parsed - the same handler will still get called allowing the client to stop or do whatever etc. The only difference is when the callback is called, and since it's a callback, the client can still handle the error as it did before. In practice, they both just get manifested as warnings most of the time, so the timing difference looks weird to most clients.

Whilst I get your point about simpler control flow, we are currently in a slightly weird hybrid situation where sometimes we use a callback and other times we return the error, so in some ways, I think this idea simplifies the interface.

I'll try to get my follow-up patch up for review to illustrate.

[jhenderson]

Rebase and use Rows.size() to identify whether a new line should be printed.

[jhenderson]

@dblaikie, I think the issues surrounding the error messages are best dealt with in D81165 (or other patches replacing that one). Would you be happy for this patch to land (possibly without the FIXME) in its current state? The bulk of it is improving the state of things (see the differences in behaviour indicated by the test changes, for example.

[dblaikie]

In D81102#2079581, @jhenderson wrote:

@dblaikie, I think the issues surrounding the error messages are best dealt with in D81165 (or other patches replacing that one). Would you be happy for this patch to land (possibly without the FIXME) in its current state? The bulk of it is improving the state of things (see the differences in behaviour indicated by the test changes, for example.

Sure - please remove the FIXME either now or later/once D81165 is resolved in some way.

llvm/lib/DebugInfo/DWARF/DWARFDebugLine.cpp

Error PrologueErr =
       Prologue.parse(DebugLineData, OffsetPtr, RecoverableErrorHandler, Ctx, U);
 
   if (OS) {
     DIDumpOptions DumpOptions;
     DumpOptions.Verbose = Verbose;
     Prologue.dump(*OS, DumpOptions);
   }
 
-  if (PrologueErr)
+  if (PrologueErr) {
+    // Ensure there is a blank line after the prologue to clearly delineate it
+    // from later dumps.
+    if (OS)
+      *OS << "\n";
+    // FIXME: Rather than return this error, we should handle it here in a
+    // callback, so that the error will (if printed) be placed before the new
+    // line above.
     return PrologueErr;
+  }
 
   uint64_t ProgramLength = Prologue.TotalLength + Prologue.sizeofTotalLength();
   if (!DebugLineData.isValidOffsetForDataOfSize(DebugLineOffset,
                                                 ProgramLength)) {
     assert(DebugLineData.size() > DebugLineOffset &&
            "prologue parsing should handle invalid offset");
     uint64_t BytesRemaining = DebugLineData.size() - DebugLineOffset;
     RecoverableErrorHandler(
if (OS && *OffsetPtr < EndOffset) {
     Row::dumpTableHeader(*OS, 12);
   }
   while (*OffsetPtr < EndOffset) {
     if (Verbose)
       *OS << format("0x%08.08" PRIx64 ": ", *OffsetPtr);
 
     uint64_t OpcodeOffset = *OffsetPtr;
     uint8_t Opcode = TableData.getU8(OffsetPtr);
+    size_t RowCount = Rows.size();
 
     if (Verbose)
       *OS << format("%02.02" PRIx8 " ", Opcode);
 
     if (Opcode == 0) {
       // Extended Opcodes always start with a zero opcode followed by
       // a uleb128 length so you can skip ones you don't know about
       DataExtractor::Cursor Cursor(*OffsetPtr);
if (Opcode == 0) {
         // Takes no arguments. Append a row to the matrix using the
         // current values of the state-machine registers.
         if (Verbose) {
           *OS << "\n";
           OS->indent(12);
         }
         if (OS)
           State.Row.dump(*OS);
-        if (Verbose) // FIXME: Don't print this newline.
-          *OS << "\n";
         State.appendRowToMatrix();
         break;
 
       case DW_LNS_advance_pc:
         // Takes a single unsigned LEB128 operand, multiplies it by the
         // min_inst_length field of the prologue, and adds the
         // result to the address register of the state machine.
         {
if (Opcode == 0) {
         *OS << "address += " << Delta.Address << ",  line += " << Delta.Line
             << "\n";
         OS->indent(12);
       }
       if (OS)
         State.Row.dump(*OS);
 
       State.appendRowToMatrix();
     }
-    if(Verbose)
+
+    // When a row is added to the matrix, it is also dumped, which includes a
+    // new line already, so don't add an extra one.
+    if (Verbose && Rows.size() == RowCount)
       *OS << "\n";
   }
 
   if (!State.Sequence.Empty)
     RecoverableErrorHandler(createStringError(
         errc::illegal_byte_sequence,
         "last sequence in debug line table at offset 0x%8.8" PRIx64
         " is not terminated",

llvm/test/tools/llvm-dwarfdump/X86/debug_line_invalid.test

 ## For non-fatal issues, the table data should be dumped:
 
 ## Version 0 table.
 # NONFATAL:      debug_line[0x00000048]
 # NONFATAL-NEXT: Line table prologue
 # NONFATAL-NEXT:    total_length: 0x00000002
 # NONFATAL-NEXT:          format: DWARF32
 # NONFATAL-NEXT:         version: 0
+# NONFATAL-EMPTY:
 # SOME-ERR-NEXT: warning: parsing line table prologue at offset 0x00000048: unsupported version 0
-# NONFATAL-NOT: prologue_length
 
 ## Version 1 table.
 # NONFATAL:      debug_line[0x0000004e]
 # NONFATAL-NEXT: Line table prologue
 # NONFATAL-NEXT:    total_length: 0x00000002
 # NONFATAL-NEXT:          format: DWARF32
 # NONFATAL-NEXT:         version: 1
+# NONFATAL-EMPTY:
 # SOME-ERR-NEXT: warning: parsing line table prologue at offset 0x0000004e: unsupported version 1
-# NONFATAL-NOT: prologue_length
 
 ## Malformed directory format with no path component.
 # NONFATAL:      debug_line[0x00000054]
 # SOME-ERR-NEXT: warning: parsing line table prologue at 0x00000054 found an invalid directory or file table description at 0x00000073
 # SOME-ERR-NEXT: warning: failed to parse entry content descriptions because no path was found
 # NONFATAL-NEXT: Line table prologue
 # NONFATAL:      prologue_length: 0x00000013
 # NONFATAL-NOT:  include_directories

llvm/test/tools/llvm-dwarfdump/X86/verbose.test

 #       CHECK:.debug_line contents:
 #       CHECK:         length: 0x00000000
 # CHECK-EMPTY:
 #  CHECK-NEXT:            Address            Line   Column File   ISA Discriminator Flags
 #  CHECK-NEXT:            ------------------ ------ ------ ------ --- ------------- -------------
 #  CHECK-NEXT:0x00000029: 00 DW_LNE_set_address (0x0000000000000000)
 #  CHECK-NEXT:0x00000034: 01 DW_LNS_copy
 #  CHECK-NEXT:            0x0000000000000000      1      0      1   0             0  is_stmt
-# CHECK-EMPTY:
-# CHECK-EMPTY:
-#       CHECK:0x00000035: 05 DW_LNS_set_column (12)
+#  CHECK-NEXT:0x00000035: 05 DW_LNS_set_column (12)
 #  CHECK-NEXT:0x00000037: 0a DW_LNS_set_prologue_end
 #  CHECK-NEXT:0x00000038: 66 address += 6,  line += 0
 #  CHECK-NEXT:            0x0000000000000006      1     12      1   0             0  is_stmt prologue_end
-# CHECK-EMPTY:
 #  CHECK-NEXT:0x00000039: 02 DW_LNS_advance_pc (2)
 #  CHECK-NEXT:0x0000003b: 00 DW_LNE_end_sequence
 #  CHECK-NEXT:            0x0000000000000008      1     12      1   0             0  is_stmt end_sequence
 # CHECK-EMPTY:
 
 #   CHECK-NOT:{{.*}} contents:

llvm/unittests/DebugInfo/DWARF/DWARFDebugLineTest.cpp

TEST_F(DebugLineBasicFixture, ParserIgnoresNonPrologueErrorsWhenSkipping) {
   DWARFDebugLine::SectionParser Parser(LineData, *Context, CUs, TUs);
   Parser.skip(RecordRecoverable, RecordUnrecoverable);
 
   EXPECT_TRUE(Parser.done());
   EXPECT_FALSE(Recoverable);
   EXPECT_FALSE(Unrecoverable);
 }
 
-TEST_F(DebugLineBasicFixture, ParserPrintsStandardOpcodesWhenRequested) {
-  if (!setupGenerator())
+TEST_F(DebugLineBasicFixture, VerboseOutput) {
+  if (!setupGenerator(5))
     return;
 
-  using ValLen = dwarfgen::LineTable::ValueAndLength;
-  LineTable &LT = Gen->addLineTable(DWARF32);
+  LineTable &LT = Gen->addLineTable();
+  LT.addByte(0); // Extended opcode with zero length.
+  LT.addByte(0);
+  // Zero-value extended opcode.
+  LT.addExtendedOpcode(2, 0, {{1, LineTable::Byte}});
+  // Unknown extended opcode.
+  LT.addExtendedOpcode(2, 0x42, {{1, LineTable::Byte}});
+  LT.addExtendedOpcode(9, DW_LNE_set_address,
+                       {{0x123456789abcdef, LineTable::Quad}});
+  LT.addExtendedOpcode(6, DW_LNE_define_file,
+                       {{'a', LineTable::Byte},
+                        {'\0', LineTable::Byte},
+                        {2, LineTable::ULEB},
+                        {3, LineTable::ULEB},
+                        {4, LineTable::ULEB}});
+  LT.addExtendedOpcode(2, DW_LNE_set_discriminator, {{0x7f, LineTable::ULEB}});
   LT.addStandardOpcode(DW_LNS_copy, {});
-  LT.addStandardOpcode(DW_LNS_advance_pc, {ValLen{11, LineTable::ULEB}});
-  LT.addStandardOpcode(DW_LNS_advance_line, {ValLen{22, LineTable::SLEB}});
-  LT.addStandardOpcode(DW_LNS_set_file, {ValLen{33, LineTable::ULEB}});
-  LT.addStandardOpcode(DW_LNS_set_column, {ValLen{44, LineTable::ULEB}});
+  LT.addStandardOpcode(DW_LNS_advance_pc, {{11, LineTable::ULEB}});
+  LT.addStandardOpcode(DW_LNS_advance_line, {{22, LineTable::SLEB}});
+  LT.addStandardOpcode(DW_LNS_set_file, {{33, LineTable::ULEB}});
+  LT.addStandardOpcode(DW_LNS_set_column, {{44, LineTable::ULEB}});
   LT.addStandardOpcode(DW_LNS_negate_stmt, {});
   LT.addStandardOpcode(DW_LNS_set_basic_block, {});
   LT.addStandardOpcode(DW_LNS_const_add_pc, {});
-  LT.addStandardOpcode(DW_LNS_fixed_advance_pc, {ValLen{55, LineTable::Half}});
+  LT.addStandardOpcode(DW_LNS_fixed_advance_pc, {{55, LineTable::Half}});
   LT.addStandardOpcode(DW_LNS_set_prologue_end, {});
   LT.addStandardOpcode(DW_LNS_set_epilogue_begin, {});
-  LT.addStandardOpcode(DW_LNS_set_isa, {ValLen{66, LineTable::ULEB}});
+  LT.addStandardOpcode(DW_LNS_set_isa, {{66, LineTable::ULEB}});
+  // Add unknown standard opcode.
+  LT.addStandardOpcode(
+      0xd, {{1, LineTable::ULEB}, {0x123456789abcdef, LineTable::ULEB}});
+  LT.addByte(0xff); // Special opcode.
   LT.addExtendedOpcode(1, DW_LNE_end_sequence, {});
+
+  // Adjust the prologue to account for the extra standard opcode.
+  DWARFDebugLine::Prologue Prologue = LT.createBasicPrologue();
+  ++Prologue.TotalLength;
+  ++Prologue.PrologueLength;
+  ++Prologue.OpcodeBase;
+  Prologue.StandardOpcodeLengths.push_back(2);
+  LT.setPrologue(Prologue);
+
   generate();
 
   DWARFDebugLine::SectionParser Parser(LineData, *Context, CUs, TUs);
   std::string Output;
   raw_string_ostream OS(Output);
   Parser.parseNext(RecordRecoverable, RecordUnrecoverable, &OS,
                    /*Verbose=*/true);
   OS.flush();
+  StringRef OutputRef(Output);
 
-  EXPECT_FALSE(Recoverable);
-  EXPECT_FALSE(Unrecoverable);
-  auto InOutput = [&Output](char const *Str) {
-    return Output.find(Str) != std::string::npos;
+  size_t Pos = 0;
+  auto NextLine = [&Pos, &OutputRef]() {
+    size_t EOL = OutputRef.find_first_of('\n', Pos);
+    StringRef Line = OutputRef.substr(Pos, EOL - Pos);
+    Pos = EOL + 1;
+    return Line;
   };
-  EXPECT_TRUE(InOutput("0x0000002e: 01 DW_LNS_copy\n")) << Output;
-  EXPECT_TRUE(InOutput("0x0000002f: 02 DW_LNS_advance_pc (11)\n")) << Output;
-  // FIXME: The value printed after DW_LNS_advance_line is currently the result
-  // of the advance, but it should be the value being advanced by. See
-  // https://bugs.llvm.org/show_bug.cgi?id=44261 for details.
-  EXPECT_TRUE(InOutput("0x00000031: 03 DW_LNS_advance_line (23)\n")) << Output;
-  EXPECT_TRUE(InOutput("0x00000033: 04 DW_LNS_set_file (33)\n")) << Output;
-  EXPECT_TRUE(InOutput("0x00000035: 05 DW_LNS_set_column (44)\n")) << Output;
-  EXPECT_TRUE(InOutput("0x00000037: 06 DW_LNS_negate_stmt\n")) << Output;
-  EXPECT_TRUE(InOutput("0x00000038: 07 DW_LNS_set_basic_block\n")) << Output;
-  EXPECT_TRUE(
-      InOutput("0x00000039: 08 DW_LNS_const_add_pc (0x0000000000000011)\n"))
-      << Output;
-  EXPECT_TRUE(InOutput("0x0000003a: 09 DW_LNS_fixed_advance_pc (0x0037)\n"))
-      << Output;
-  EXPECT_TRUE(InOutput("0x0000003d: 0a DW_LNS_set_prologue_end\n")) << Output;
-  EXPECT_TRUE(InOutput("0x0000003e: 0b DW_LNS_set_epilogue_begin\n")) << Output;
-  EXPECT_TRUE(InOutput("0x0000003f: 0c DW_LNS_set_isa (66)\n")) << Output;
+  EXPECT_EQ(NextLine(), "Line table prologue:");
+  EXPECT_EQ(NextLine(), "    total_length: 0x00000076");
+  EXPECT_EQ(NextLine(), "          format: DWARF32");
+  EXPECT_EQ(NextLine(), "         version: 5");
+  EXPECT_EQ(NextLine(), "    address_size: 8");
+  EXPECT_EQ(NextLine(), " seg_select_size: 0");
+  EXPECT_EQ(NextLine(), " prologue_length: 0x0000002b");
+  EXPECT_EQ(NextLine(), " min_inst_length: 1");
+  EXPECT_EQ(NextLine(), "max_ops_per_inst: 1");
+  EXPECT_EQ(NextLine(), " default_is_stmt: 1");
+  EXPECT_EQ(NextLine(), "       line_base: -5");
+  EXPECT_EQ(NextLine(), "      line_range: 14");
+  EXPECT_EQ(NextLine(), "     opcode_base: 14");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_copy] = 0");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_advance_pc] = 1");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_advance_line] = 1");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_set_file] = 1");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_set_column] = 1");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_negate_stmt] = 0");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_set_basic_block] = 0");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_const_add_pc] = 0");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_fixed_advance_pc] = 1");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_set_prologue_end] = 0");
+  EXPECT_EQ(NextLine(),
+            "standard_opcode_lengths[DW_LNS_set_epilogue_begin] = 0");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_set_isa] = 1");
+  EXPECT_EQ(NextLine(), "standard_opcode_lengths[DW_LNS_unknown_d] = 2");
+  EXPECT_EQ(NextLine(), "include_directories[  0] = \"a dir\"");
+  EXPECT_EQ(NextLine(), "file_names[  0]:");
+  EXPECT_EQ(NextLine(), "           name: \"a file\"");
+  EXPECT_EQ(NextLine(), "      dir_index: 0");
+  EXPECT_EQ(NextLine(), "");
+  EXPECT_EQ(NextLine(), "            Address            Line   Column File   ISA Discriminator Flags");
+  EXPECT_EQ(NextLine(), "            ------------------ ------ ------ ------ --- ------------- -------------");
+  EXPECT_EQ(NextLine(),
+            "0x00000037: 00 Badly formed extended line op (length 0)");
+  EXPECT_EQ(NextLine(),
+            "0x00000039: 00 Unrecognized extended op 0x00 length 2");
+  EXPECT_EQ(NextLine(),
+            "0x0000003d: 00 Unrecognized extended op 0x42 length 2");
+  EXPECT_EQ(NextLine(),
+            "0x00000041: 00 DW_LNE_set_address (0x0123456789abcdef)");
+  EXPECT_EQ(NextLine(), "0x0000004c: 00 DW_LNE_define_file (a, dir=2, "
+                        "mod_time=(0x0000000000000003), length=4)");
+  EXPECT_EQ(NextLine(), "0x00000054: 00 DW_LNE_set_discriminator (127)");
+  EXPECT_EQ(NextLine(), "0x00000058: 01 DW_LNS_copy");
+  EXPECT_EQ(NextLine(), "            0x0123456789abcdef      1      0      1   "
+                        "0           127  is_stmt");
+  EXPECT_EQ(NextLine(), "0x00000059: 02 DW_LNS_advance_pc (11)");
+  EXPECT_EQ(NextLine(), "0x0000005b: 03 DW_LNS_advance_line (23)");
+  EXPECT_EQ(NextLine(), "0x0000005d: 04 DW_LNS_set_file (33)");
+  EXPECT_EQ(NextLine(), "0x0000005f: 05 DW_LNS_set_column (44)");
+  EXPECT_EQ(NextLine(), "0x00000061: 06 DW_LNS_negate_stmt");
+  EXPECT_EQ(NextLine(), "0x00000062: 07 DW_LNS_set_basic_block");
+  EXPECT_EQ(NextLine(),
+            "0x00000063: 08 DW_LNS_const_add_pc (0x0000000000000011)");
+  EXPECT_EQ(NextLine(), "0x00000064: 09 DW_LNS_fixed_advance_pc (0x0037)");
+  EXPECT_EQ(NextLine(), "0x00000067: 0a DW_LNS_set_prologue_end");
+  EXPECT_EQ(NextLine(), "0x00000068: 0b DW_LNS_set_epilogue_begin");
+  EXPECT_EQ(NextLine(), "0x00000069: 0c DW_LNS_set_isa (66)");
+  EXPECT_EQ(NextLine(),
+            "0x0000006b: 0d Skipping ULEB128 value: 0x0000000000000001)");
+  EXPECT_EQ(NextLine(), "Skipping ULEB128 value: 0x0123456789abcdef)");
+  EXPECT_EQ(NextLine(), "");
+  EXPECT_EQ(NextLine(), "0x00000076: ff address += 17,  line += -2");
+  EXPECT_EQ(NextLine(),
+            "            0x0123456789abce53     21     44     33  66           "
+            "  0  basic_block prologue_end epilogue_begin");
+  EXPECT_EQ(NextLine(), "0x00000077: 00 DW_LNE_end_sequence");
+  EXPECT_EQ(NextLine(), "            0x0123456789abce53     21     44     33  "
+                        "66             0  end_sequence");
+  EXPECT_EQ(NextLine(), "");
+  EXPECT_EQ(Output.size(), Pos);
 }
 
 using ValueAndLengths = std::vector<LineTable::ValueAndLength>;
 
 struct TruncatedExtendedOpcodeFixture
     : public TestWithParam<std::tuple<uint64_t, uint64_t, uint8_t,
                                       ValueAndLengths, StringRef, StringRef>>,
       public CommonFixture {