mirrors/llvm-project
0
0
Fork 0
mirror of https://github.com/llvm/llvm-project.git synced 2025-04-28 17:46:04 +00:00
Code Issues Projects Releases Wiki Activity
llvm-project/lldb/source/Target/TraceDumper.cpp

Ignoring revisions in .git-blame-ignore-revs. Click here to bypass and see the normal blame view.

427 lines
14 KiB
C++
Raw Normal View History

[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
//===-- TraceDumper.cpp ---------------------------------------------------===//
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
//
// 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
//
//===----------------------------------------------------------------------===//
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
#include "lldb/Target/TraceDumper.h"
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
#include "lldb/Core/Module.h"
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
#include "lldb/Symbol/CompileUnit.h"
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
#include "lldb/Symbol/Function.h"
#include "lldb/Target/ExecutionContext.h"
#include "lldb/Target/Process.h"
#include "lldb/Target/SectionLoadList.h"
using namespace lldb;
using namespace lldb_private;
using namespace llvm;
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
/// \return
/// The given string or \b None if it's empty.
static Optional<const char *> ToOptionalString(const char *s) {
if (!s)
return None;
return s;
[trace][intelpt] Introduce instruction Ids In order to support quick arbitrary access to instructions in the trace, we need each instruction to have an id. It could be an index or any other value that the trace plugin defines. This will be useful for reverse debugging or for creating callstacks, as each frame will need an instruction id associated with them. I've updated the `thread trace dump instructions` command accordingly. It now prints the instruction id instead of relative offset. I've also added a new --id argument that allows starting the dump from an arbitrary position. Differential Revision: https://reviews.llvm.org/D122254
2022-03-22 09:18:53 -07:00
}
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
/// \return
/// The module name (basename if the module is a file, or the actual name if
/// it's a virtual module), or \b nullptr if no name nor module was found.
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
static const char *GetModuleName(const TraceDumper::TraceItem &item) {
if (!item.symbol_info || !item.symbol_info->sc.module_sp)
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
return nullptr;
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
return item.symbol_info->sc.module_sp->GetFileSpec()
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
.GetFilename()
.AsCString();
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
}
// This custom LineEntry validator is neded because some line_entries have
// 0 as line, which is meaningless. Notice that LineEntry::IsValid only
// checks that line is not LLDB_INVALID_LINE_NUMBER, i.e. UINT32_MAX.
static bool IsLineEntryValid(const LineEntry &line_entry) {
return line_entry.IsValid() && line_entry.line > 0;
}
/// \return
/// \b true if the provided line entries match line, column and source file.
/// This function assumes that the line entries are valid.
static bool FileLineAndColumnMatches(const LineEntry &a, const LineEntry &b) {
if (a.line != b.line)
return false;
if (a.column != b.column)
return false;
return a.file == b.file;
}
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
/// Compare the symbol contexts of the provided \a SymbolInfo
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
/// objects.
///
/// \return
/// \a true if both instructions belong to the same scope level analized
/// in the following order:
/// - module
/// - symbol
/// - function
/// - line
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
static bool
IsSameInstructionSymbolContext(const TraceDumper::SymbolInfo &prev_insn,
const TraceDumper::SymbolInfo &insn) {
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
// module checks
if (insn.sc.module_sp != prev_insn.sc.module_sp)
return false;
// symbol checks
if (insn.sc.symbol != prev_insn.sc.symbol)
return false;
// function checks
if (!insn.sc.function && !prev_insn.sc.function)
return true;
else if (insn.sc.function != prev_insn.sc.function)
return false;
// line entry checks
const bool curr_line_valid = IsLineEntryValid(insn.sc.line_entry);
const bool prev_line_valid = IsLineEntryValid(prev_insn.sc.line_entry);
if (curr_line_valid && prev_line_valid)
return FileLineAndColumnMatches(insn.sc.line_entry,
prev_insn.sc.line_entry);
return curr_line_valid == prev_line_valid;
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
class OutputWriterCLI : public TraceDumper::OutputWriter {
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
public:
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
OutputWriterCLI(Stream &s, const TraceDumperOptions &options, Thread &thread)
: m_s(s), m_options(options) {
m_s.Format("thread #{0}: tid = {1}\n", thread.GetIndexID(), thread.GetID());
};
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
void NoMoreData() override { m_s << " no more data\n"; }
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
void TraceItem(const TraceDumper::TraceItem &item) override {
if (item.symbol_info) {
if (!item.prev_symbol_info ||
!IsSameInstructionSymbolContext(*item.prev_symbol_info,
*item.symbol_info)) {
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
m_s << " ";
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
const char *module_name = GetModuleName(item);
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
if (!module_name)
m_s << "(none)";
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
else if (!item.symbol_info->sc.function && !item.symbol_info->sc.symbol)
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
m_s.Format("{0}`(none)", module_name);
else
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
item.symbol_info->sc.DumpStopContext(
&m_s, item.symbol_info->exe_ctx.GetTargetPtr(),
item.symbol_info->address,
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
/*show_fullpaths=*/false,
/*show_module=*/true, /*show_inlined_frames=*/false,
/*show_function_arguments=*/true,
/*show_function_name=*/true);
m_s << "\n";
}
}
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
if (item.error && !m_was_prev_instruction_an_error)
m_s << " ...missing instructions\n";
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
m_s.Format(" {0}: ", item.id);
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
if (m_options.show_timestamps) {
m_s.Format("[{0}] ", item.timestamp
? formatv("{0:3} ns", *item.timestamp).str()
: "unavailable");
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
if (item.event) {
m_s << "(event) " << TraceCursor::EventKindToString(*item.event);
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
switch (*item.event) {
case eTraceEventCPUChanged:
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
m_s.Format(" [new CPU={0}]",
item.cpu_id ? std::to_string(*item.cpu_id) : "unavailable");
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
break;
case eTraceEventHWClockTick:
m_s.Format(" [{0}]", item.hw_clock ? std::to_string(*item.hw_clock)
: "unavailable");
break;
case eTraceEventDisabledHW:
case eTraceEventDisabledSW:
break;
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
} else if (item.error) {
m_s << "(error) " << *item.error;
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
} else {
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
m_s.Format("{0:x+16}", item.load_address);
[trace] Avoid a crash in the dumper when disassembling fails In rare situations, disassemblying would fail that produce an invalid InstructionSP object. We need to check that it's valid before using. With this change, now the dumper doesn't crash with dumping instructions of ioctl. In fact, it now dumps this output { "id": 6135, "loadAddress": "0x7f4bfe5c7515", "module": "libc.so.6", "symbol": "ioctl", "source": "glibc/2.34/src/glibc-2.34/sysdeps/unix/syscall-template.S", "line": 120, "column": 0 } Anyway, we need to investigate why the diassembler failed disassembling that instruction. From over 2B instructions I was disassembling today, just this one failed, so this could be a bug in LLVM's core disassembler. Differential Revision: https://reviews.llvm.org/D129588
2022-07-12 12:41:30 -07:00
if (item.symbol_info && item.symbol_info->instruction) {
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
m_s << " ";
[trace] Add a flag to the decoder to output the instruction type To build complex binding upon instruction trace, additional metadata 'instruction type' is needed. This diff has followings: - Add a flag -k / --kind for instruction dump - Remove SetGranularity and SetIgnoreErros from Trace cursor Sample output: ``` (lldb) thread trace dump instruction -k thread #1: tid = 3198805 libc.so.6`_IO_puts + 356 2107: 0x00007ffff7163594 ( return) retq 2106: 0x00007ffff7163592 ( other) popq %r13 2105: 0x00007ffff7163590 ( other) popq %r12 2104: 0x00007ffff716358f ( other) popq %rbp 2103: 0x00007ffff716358e ( other) popq %rbx 2102: 0x00007ffff716358c ( other) movl %ebx, %eax 2101: 0x00007ffff7163588 ( other) addq $0x8, %rsp 2100: 0x00007ffff7163570 ( cond jump) je 0x89588 ; <+344> 2099: 0x00007ffff716356e ( other) decl (%rdx) 2098: 0x00007ffff7163565 ( cond jump) je 0x8956e ; <+318> 2097: 0x00007ffff716355e ( other) cmpl $0x0, 0x33c02b(%rip) ; __libc_multiple_threads 2096: 0x00007ffff7163556 ( other) movq $0x0, 0x8(%rdx) 2095: 0x00007ffff7163554 ( cond jump) jne 0x89588 ; <+344> 2094: 0x00007ffff7163550 ( other) subl $0x1, 0x4(%rdx) 2093: 0x00007ffff7163549 ( other) movq 0x88(%rbp), %rdx 2092: 0x00007ffff7163547 ( cond jump) jne 0x89588 ; <+344> 2091: 0x00007ffff7163540 ( other) testl $0x8000, (%rbp) ; imm = 0x8000 2090: 0x00007ffff716353c ( other) cmovaq %rax, %rbx 2089: 0x00007ffff7163535 ( other) cmpq $0x7fffffff, %rbx ; imm = 0x7FFFFFFF 2088: 0x00007ffff7163530 ( other) movl $0x7fffffff, %eax ; imm = 0x7FFFFFFF ``` Reviewed By: wallace Differential Revision: https://reviews.llvm.org/D128477
2022-07-12 16:09:03 -07:00
item.symbol_info->instruction->Dump(
&m_s, /*max_opcode_byte_size=*/0,
/*show_address=*/false,
/*show_bytes=*/false, m_options.show_control_flow_kind,
&item.symbol_info->exe_ctx, &item.symbol_info->sc,
/*prev_sym_ctx=*/nullptr,
/*disassembly_addr_format=*/nullptr,
/*max_address_text_size=*/0);
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
}
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
m_was_prev_instruction_an_error = (bool)item.error;
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
m_s << "\n";
}
private:
Stream &m_s;
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
TraceDumperOptions m_options;
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
bool m_was_prev_instruction_an_error = false;
};
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
class OutputWriterJSON : public TraceDumper::OutputWriter {
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
/* schema:
error_message: string
| {
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
"event": string,
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
"id": decimal,
"tsc"?: string decimal,
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
"cpuId"? decimal,
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
} | {
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
"error": string,
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
"id": decimal,
"tsc"?: string decimal,
| {
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
"loadAddress": string decimal,
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
"id": decimal,
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
"hwClock"?: string decimal,
"timestamp_ns"?: string decimal,
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
"module"?: string,
"symbol"?: string,
"line"?: decimal,
"column"?: decimal,
"source"?: string,
"mnemonic"?: string,
}
*/
public:
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
OutputWriterJSON(Stream &s, const TraceDumperOptions &options)
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
: m_s(s), m_options(options),
m_j(m_s.AsRawOstream(),
/*IndentSize=*/options.pretty_print_json ? 2 : 0) {
m_j.arrayBegin();
};
~OutputWriterJSON() { m_j.arrayEnd(); }
[trace] Avoid a crash in the dumper when disassembling fails In rare situations, disassemblying would fail that produce an invalid InstructionSP object. We need to check that it's valid before using. With this change, now the dumper doesn't crash with dumping instructions of ioctl. In fact, it now dumps this output { "id": 6135, "loadAddress": "0x7f4bfe5c7515", "module": "libc.so.6", "symbol": "ioctl", "source": "glibc/2.34/src/glibc-2.34/sysdeps/unix/syscall-template.S", "line": 120, "column": 0 } Anyway, we need to investigate why the diassembler failed disassembling that instruction. From over 2B instructions I was disassembling today, just this one failed, so this could be a bug in LLVM's core disassembler. Differential Revision: https://reviews.llvm.org/D129588
2022-07-12 12:41:30 -07:00
void DumpEvent(const TraceDumper::TraceItem &item) {
m_j.attribute("event", TraceCursor::EventKindToString(*item.event));
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
switch (*item.event) {
case eTraceEventCPUChanged:
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
m_j.attribute("cpuId", item.cpu_id);
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
break;
case eTraceEventHWClockTick:
m_j.attribute("hwClock", item.hw_clock);
break;
case eTraceEventDisabledHW:
case eTraceEventDisabledSW:
break;
}
[trace] Avoid a crash in the dumper when disassembling fails In rare situations, disassemblying would fail that produce an invalid InstructionSP object. We need to check that it's valid before using. With this change, now the dumper doesn't crash with dumping instructions of ioctl. In fact, it now dumps this output { "id": 6135, "loadAddress": "0x7f4bfe5c7515", "module": "libc.so.6", "symbol": "ioctl", "source": "glibc/2.34/src/glibc-2.34/sysdeps/unix/syscall-template.S", "line": 120, "column": 0 } Anyway, we need to investigate why the diassembler failed disassembling that instruction. From over 2B instructions I was disassembling today, just this one failed, so this could be a bug in LLVM's core disassembler. Differential Revision: https://reviews.llvm.org/D129588
2022-07-12 12:41:30 -07:00
}
void DumpInstruction(const TraceDumper::TraceItem &item) {
m_j.attribute("loadAddress", formatv("{0:x}", item.load_address));
if (item.symbol_info) {
m_j.attribute("module", ToOptionalString(GetModuleName(item)));
m_j.attribute(
"symbol",
ToOptionalString(item.symbol_info->sc.GetFunctionName().AsCString()));
if (item.symbol_info->instruction) {
m_j.attribute("mnemonic",
ToOptionalString(item.symbol_info->instruction->GetMnemonic(
&item.symbol_info->exe_ctx)));
}
if (IsLineEntryValid(item.symbol_info->sc.line_entry)) {
m_j.attribute(
"source",
ToOptionalString(
item.symbol_info->sc.line_entry.file.GetPath().c_str()));
m_j.attribute("line", item.symbol_info->sc.line_entry.line);
m_j.attribute("column", item.symbol_info->sc.line_entry.column);
}
}
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
void TraceItem(const TraceDumper::TraceItem &item) override {
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
m_j.object([&] {
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
m_j.attribute("id", item.id);
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
if (m_options.show_timestamps)
m_j.attribute("timestamp_ns", item.timestamp
? Optional<std::string>(
std::to_string(*item.timestamp))
: None);
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
if (item.event) {
[trace] Avoid a crash in the dumper when disassembling fails In rare situations, disassemblying would fail that produce an invalid InstructionSP object. We need to check that it's valid before using. With this change, now the dumper doesn't crash with dumping instructions of ioctl. In fact, it now dumps this output { "id": 6135, "loadAddress": "0x7f4bfe5c7515", "module": "libc.so.6", "symbol": "ioctl", "source": "glibc/2.34/src/glibc-2.34/sysdeps/unix/syscall-template.S", "line": 120, "column": 0 } Anyway, we need to investigate why the diassembler failed disassembling that instruction. From over 2B instructions I was disassembling today, just this one failed, so this could be a bug in LLVM's core disassembler. Differential Revision: https://reviews.llvm.org/D129588
2022-07-12 12:41:30 -07:00
DumpEvent(item);
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
} else if (item.error) {
m_j.attribute("error", *item.error);
} else {
DumpInstruction(item);
}
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
});
}
private:
Stream &m_s;
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
TraceDumperOptions m_options;
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
json::OStream m_j;
};
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
static std::unique_ptr<TraceDumper::OutputWriter>
CreateWriter(Stream &s, const TraceDumperOptions &options, Thread &thread) {
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
if (options.json)
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
return std::unique_ptr<TraceDumper::OutputWriter>(
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
new OutputWriterJSON(s, options));
else
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
return std::unique_ptr<TraceDumper::OutputWriter>(
new OutputWriterCLI(s, options, thread));
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
TraceDumper::TraceDumper(lldb::TraceCursorUP &&cursor_up, Stream &s,
const TraceDumperOptions &options)
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
: m_cursor_up(std::move(cursor_up)), m_options(options),
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
m_writer_up(CreateWriter(
s, m_options, *m_cursor_up->GetExecutionContextRef().GetThreadSP())) {
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
[trace] Improve the TraceCursor iteration API The current way ot traversing the cursor is a bit uncommon and it can't handle empty traces, in fact, its invariant is that it shold always point to a valid item. This diff simplifies the cursor API and allows it to point to invalid items, thus being able to handle empty traces or to know it ran out of data. - Removed all the granularity functionalities, because we are not actually making use of that. We can bring them back when they are actually needed. - change the looping logic to the following: ``` for (; cursor->HasValue(); cursor->Next()) { if (cursor->IsError()) { .. do something for error continue; } .. do something for instruction } ``` - added a HasValue method that can be used to identify if the cursor ran out of data, the trace is empty, or the user tried to move to an invalid position via SetId() or Seek() - made several simplifications to severals parts of the code. Differential Revision: https://reviews.llvm.org/D128543
2022-06-24 11:19:09 -07:00
if (m_options.id)
m_cursor_up->GoToId(*m_options.id);
else if (m_options.forwards)
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
m_cursor_up->Seek(0, TraceCursor::SeekType::Beginning);
[trace] Improve the TraceCursor iteration API The current way ot traversing the cursor is a bit uncommon and it can't handle empty traces, in fact, its invariant is that it shold always point to a valid item. This diff simplifies the cursor API and allows it to point to invalid items, thus being able to handle empty traces or to know it ran out of data. - Removed all the granularity functionalities, because we are not actually making use of that. We can bring them back when they are actually needed. - change the looping logic to the following: ``` for (; cursor->HasValue(); cursor->Next()) { if (cursor->IsError()) { .. do something for error continue; } .. do something for instruction } ``` - added a HasValue method that can be used to identify if the cursor ran out of data, the trace is empty, or the user tried to move to an invalid position via SetId() or Seek() - made several simplifications to severals parts of the code. Differential Revision: https://reviews.llvm.org/D128543
2022-06-24 11:19:09 -07:00
else
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
m_cursor_up->Seek(0, TraceCursor::SeekType::End);
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
m_cursor_up->SetForwards(m_options.forwards);
if (m_options.skip) {
[trace] Improve the TraceCursor iteration API The current way ot traversing the cursor is a bit uncommon and it can't handle empty traces, in fact, its invariant is that it shold always point to a valid item. This diff simplifies the cursor API and allows it to point to invalid items, thus being able to handle empty traces or to know it ran out of data. - Removed all the granularity functionalities, because we are not actually making use of that. We can bring them back when they are actually needed. - change the looping logic to the following: ``` for (; cursor->HasValue(); cursor->Next()) { if (cursor->IsError()) { .. do something for error continue; } .. do something for instruction } ``` - added a HasValue method that can be used to identify if the cursor ran out of data, the trace is empty, or the user tried to move to an invalid position via SetId() or Seek() - made several simplifications to severals parts of the code. Differential Revision: https://reviews.llvm.org/D128543
2022-06-24 11:19:09 -07:00
m_cursor_up->Seek((m_options.forwards ? 1 : -1) * *m_options.skip,
TraceCursor::SeekType::Current);
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
}
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
TraceDumper::TraceItem TraceDumper::CreatRawTraceItem() {
[LLDB][NFC][Reliability] Fix uninitialized variables from Coverity scan. Part 2 Improve LLDB reliability by fixing the following "uninitialized variables" static code inspection warnings from scan.coverity.com: 1476275, 1274012, 1455035, 1364789, 1454282 1467483, 1406152, 1406255, 1454837, 1454416 1467446, 1462022, 1461909, 1420566, 1327228 1367767, 1431254, 1467299, 1312678, 1431780 1454731, 1490403 Differential Revision: https://reviews.llvm.org/D130528
2022-07-25 15:52:21 -07:00
TraceItem item = {};
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
item.id = m_cursor_up->GetId();
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
if (m_options.show_timestamps)
item.timestamp = m_cursor_up->GetWallClockTime();
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
return item;
[trace][intel pt] Support events A trace might contain events traced during the target's execution. For example, a thread might be paused for some period of time due to context switches or breakpoints, which actually force a context switch. Not only that, a trace might be paused because the CPU decides to trace only a specific part of the target, like the address filtering provided by intel pt, which will cause pause events. Besides this case, other kinds of events might exist. This patch adds the method `TraceCursor::GetEvents()`` that returns the list of events that happened right before the instruction being pointed at by the cursor. Some refactors were done to make this change simpler. Besides this new API, the instruction dumper now supports the -e flag which shows pause events, like in the following example, where pauses happened due to breakpoints. ``` thread #1: tid = 2717361 a.out`main + 20 at main.cpp:27:20 0: 0x00000000004023d9 leaq -0x1200(%rbp), %rax [paused] 1: 0x00000000004023e0 movq %rax, %rdi [paused] 2: 0x00000000004023e3 callq 0x403a62 ; std::vector<int, std::allocator<int> >::vector at stl_vector.h:391:7 a.out`std::vector<int, std::allocator<int> >::vector() at stl_vector.h:391:7 3: 0x0000000000403a62 pushq %rbp 4: 0x0000000000403a63 movq %rsp, %rbp ``` The `dump info` command has also been updated and now it shows the number of instructions that have associated events. Differential Revision: https://reviews.llvm.org/D123982
2022-04-18 09:28:10 -07:00
}
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
/// Find the symbol context for the given address reusing the previous
/// instruction's symbol context when possible.
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
static SymbolContext
CalculateSymbolContext(const Address &address,
const TraceDumper::SymbolInfo &prev_symbol_info) {
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
AddressRange range;
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
if (prev_symbol_info.sc.GetAddressRange(eSymbolContextEverything, 0,
/*inline_block_range*/ false,
range) &&
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
range.Contains(address))
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
return prev_symbol_info.sc;
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
SymbolContext sc;
address.CalculateSymbolContext(&sc, eSymbolContextEverything);
return sc;
}
/// Find the disassembler for the given address reusing the previous
/// instruction's disassembler when possible.
static std::tuple<DisassemblerSP, InstructionSP>
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
CalculateDisass(const TraceDumper::SymbolInfo &symbol_info,
const TraceDumper::SymbolInfo &prev_symbol_info,
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
const ExecutionContext &exe_ctx) {
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
if (prev_symbol_info.disassembler) {
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
if (InstructionSP instruction =
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
prev_symbol_info.disassembler->GetInstructionList()
.GetInstructionAtAddress(symbol_info.address))
return std::make_tuple(prev_symbol_info.disassembler, instruction);
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
}
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
if (symbol_info.sc.function) {
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
if (DisassemblerSP disassembler =
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
symbol_info.sc.function->GetInstructions(exe_ctx, nullptr)) {
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
if (InstructionSP instruction =
disassembler->GetInstructionList().GetInstructionAtAddress(
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
symbol_info.address))
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
return std::make_tuple(disassembler, instruction);
}
}
// We fallback to a single instruction disassembler
Target &target = exe_ctx.GetTargetRef();
const ArchSpec arch = target.GetArchitecture();
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
AddressRange range(symbol_info.address, arch.GetMaximumOpcodeByteSize());
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
DisassemblerSP disassembler =
Disassembler::DisassembleRange(arch, /*plugin_name*/ nullptr,
/*flavor*/ nullptr, target, range);
return std::make_tuple(
disassembler,
disassembler ? disassembler->GetInstructionList().GetInstructionAtAddress(
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
symbol_info.address)
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
: InstructionSP());
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
Optional<lldb::user_id_t> TraceDumper::DumpInstructions(size_t count) {
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
ThreadSP thread_sp = m_cursor_up->GetExecutionContextRef().GetThreadSP();
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
SymbolInfo prev_symbol_info;
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
Optional<lldb::user_id_t> last_id;
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
ExecutionContext exe_ctx;
[NFC][trace] simplify the instruction dumper TraceInstructionDumper::DumpInstructions was becoming too big, so I'm refactoring it into smaller functions. I also made some static methods proper instance methods to simplify calls. Other minor improvements are also done. Differential Revision: https://reviews.llvm.org/D124064
2022-04-19 21:57:31 -07:00
thread_sp->GetProcess()->GetTarget().CalculateExecutionContext(exe_ctx);
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
for (size_t insn_seen = 0; insn_seen < count && m_cursor_up->HasValue();
m_cursor_up->Next()) {
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
last_id = m_cursor_up->GetId();
TraceItem item = CreatRawTraceItem();
if (m_cursor_up->IsEvent()) {
if (!m_options.show_events)
continue;
item.event = m_cursor_up->GetEventType();
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
switch (*item.event) {
case eTraceEventCPUChanged:
[trace][intel pt] Create a CPU change event and expose it in the dumper Thanks to fredzhou@fb.com for coming up with this feature. When tracing in per-cpu mode, we have information of in which cpu we are execution each instruction, which comes from the context switch trace. This diff makes this information available as a `cpu changed event`, which an additional accessor in the cursor `GetCPU()`. As cpu changes are very infrequent, any consumer should listen to cpu change events instead of querying the actual cpu of a trace item. Once a cpu change event is seen, the consumer can invoke GetCPU() to get that information. Also, it's possible to invoke GetCPU() on an arbitrary instruction item, which will return the last cpu seen. However, this call is O(logn) and should be used sparingly. Manually tested with a sample program that starts on cpu 52, then goes to 18, and then goes back to 52. Differential Revision: https://reviews.llvm.org/D129340
2022-07-07 18:31:18 -07:00
item.cpu_id = m_cursor_up->GetCPU();
[trace][intel pt] Introduce wall clock time for each trace item - Decouple TSCs from trace items - Turn TSCs into events just like CPUs. The new name is HW clock tick, wich could be reused by other vendors. - Add a GetWallTime that returns the wall time that the trace plug-in can infer for each trace item. - For intel pt, we are doing the following interpolation: if an instruction takes less than 1 TSC, we use that duration, otherwise, we assume the instruction took 1 TSC. This helps us avoid having to handle context switches, changes to kernel, idle times, decoding errors, etc. We are just trying to show some approximation and not the real data. For the real data, TSCs are the way to go. Besides that, we are making sure that no two trace items will give the same interpolation value. Finally, we are using as time 0 the time at which tracing started. Sample output: ``` (lldb) r Process 750047 launched: '/home/wallace/a.out' (x86_64) Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 1.1 frame #0: 0x0000000000402479 a.out`main at main.cpp:29:20 26 }; 27 28 int main() { -> 29 std::vector<int> vvv; 30 for (int i = 0; i < 100; i++) 31 vvv.push_back(i); 32 (lldb) process trace start -s 64kb -t --per-cpu (lldb) b 60 Breakpoint 2: where = a.out`main + 1689 at main.cpp:60:23, address = 0x0000000000402afe (lldb) c Process 750047 resuming Process 750047 stopped * thread #1, name = 'a.out', stop reason = breakpoint 2.1 frame #0: 0x0000000000402afe a.out`main at main.cpp:60:23 57 map<int, int> m; 58 m[3] = 4; 59 -> 60 map<string, string> m2; 61 m2["5"] = "6"; 62 63 std::vector<std::string> vs = {"2", "3"}; (lldb) thread trace dump instructions -t -f -e thread #1: tid = 750047 0: [379567.000 ns] (event) HW clock tick [48599428476224707] 1: [379569.000 ns] (event) CPU core changed [new CPU=2] 2: [390487.000 ns] (event) HW clock tick [48599428476246495] 3: [1602508.000 ns] (event) HW clock tick [48599428478664855] 4: [1662745.000 ns] (event) HW clock tick [48599428478785046] libc.so.6`malloc 5: [1662746.995 ns] 0x00007ffff7176660 endbr64 6: [1662748.991 ns] 0x00007ffff7176664 movq 0x32387d(%rip), %rax ; + 408 7: [1662750.986 ns] 0x00007ffff717666b pushq %r12 8: [1662752.981 ns] 0x00007ffff717666d pushq %rbp 9: [1662754.977 ns] 0x00007ffff717666e pushq %rbx 10: [1662756.972 ns] 0x00007ffff717666f movq (%rax), %rax 11: [1662758.967 ns] 0x00007ffff7176672 testq %rax, %rax 12: [1662760.963 ns] 0x00007ffff7176675 jne 0x9c7e0 ; <+384> 13: [1662762.958 ns] 0x00007ffff717667b leaq 0x17(%rdi), %rax 14: [1662764.953 ns] 0x00007ffff717667f cmpq $0x1f, %rax 15: [1662766.949 ns] 0x00007ffff7176683 ja 0x9c730 ; <+208> 16: [1662768.944 ns] 0x00007ffff7176730 andq $-0x10, %rax 17: [1662770.939 ns] 0x00007ffff7176734 cmpq $-0x41, %rax 18: [1662772.935 ns] 0x00007ffff7176738 seta %dl 19: [1662774.930 ns] 0x00007ffff717673b jmp 0x9c690 ; <+48> 20: [1662776.925 ns] 0x00007ffff7176690 cmpq %rdi, %rax 21: [1662778.921 ns] 0x00007ffff7176693 jb 0x9c7b0 ; <+336> 22: [1662780.916 ns] 0x00007ffff7176699 testb %dl, %dl 23: [1662782.911 ns] 0x00007ffff717669b jne 0x9c7b0 ; <+336> 24: [1662784.906 ns] 0x00007ffff71766a1 movq 0x3236c0(%rip), %r12 ; + 24 (lldb) thread trace dump instructions -t -f -e -J -c 4 [ { "id": 0, "timestamp_ns": "379567.000000", "event": "HW clock tick", "hwClock": 48599428476224707 }, { "id": 1, "timestamp_ns": "379569.000000", "event": "CPU core changed", "cpuId": 2 }, { "id": 2, "timestamp_ns": "390487.000000", "event": "HW clock tick", "hwClock": 48599428476246495 }, { "id": 3, "timestamp_ns": "1602508.000000", "event": "HW clock tick", "hwClock": 48599428478664855 }, { "id": 4, "timestamp_ns": "1662745.000000", "event": "HW clock tick", "hwClock": 48599428478785046 }, { "id": 5, "timestamp_ns": "1662746.995324", "loadAddress": "0x7ffff7176660", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "endbr64" }, { "id": 6, "timestamp_ns": "1662748.990648", "loadAddress": "0x7ffff7176664", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "movq" }, { "id": 7, "timestamp_ns": "1662750.985972", "loadAddress": "0x7ffff717666b", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" }, { "id": 8, "timestamp_ns": "1662752.981296", "loadAddress": "0x7ffff717666d", "module": "libc.so.6", "symbol": "malloc", "mnemonic": "pushq" } ] ``` Differential Revision: https://reviews.llvm.org/D130054
2022-07-18 16:56:01 -07:00
break;
case eTraceEventHWClockTick:
item.hw_clock = m_cursor_up->GetHWClock();
break;
case eTraceEventDisabledHW:
case eTraceEventDisabledSW:
break;
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
} else if (m_cursor_up->IsError()) {
item.error = m_cursor_up->GetError();
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
} else {
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
insn_seen++;
item.load_address = m_cursor_up->GetLoadAddress();
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
[trace][intelpt] Introduce instruction Ids In order to support quick arbitrary access to instructions in the trace, we need each instruction to have an id. It could be an index or any other value that the trace plugin defines. This will be useful for reverse debugging or for creating callstacks, as each frame will need an instruction id associated with them. I've updated the `thread trace dump instructions` command accordingly. It now prints the instruction id instead of relative offset. I've also added a new --id argument that allows starting the dump from an arbitrary position. Differential Revision: https://reviews.llvm.org/D122254
2022-03-22 09:18:53 -07:00
if (!m_options.raw) {
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
SymbolInfo symbol_info;
symbol_info.exe_ctx = exe_ctx;
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
symbol_info.address.SetLoadAddress(item.load_address,
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
exe_ctx.GetTargetPtr());
symbol_info.sc =
CalculateSymbolContext(symbol_info.address, prev_symbol_info);
std::tie(symbol_info.disassembler, symbol_info.instruction) =
CalculateDisass(symbol_info, prev_symbol_info, exe_ctx);
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
item.prev_symbol_info = prev_symbol_info;
item.symbol_info = symbol_info;
[trace] Add an option to dump instructions in json and to a file In order to provide simple scripting support on top of instruction traces, a simple solution is to enhance the `dump instructions` command and allow printing in json and directly to a file. The format is verbose and not space efficient, but it's not supposed to be used for really large traces, in which case the TraceCursor API is the way to go. - add a -j option for printing the dump in json - add a -J option for pretty printing the json output - add a -F option for specifying an output file - add a -a option for dumping all the instructions available starting at the initial point configured with the other flags - add tests for all cases - refactored the instruction dumper and abstracted the actual "printing" logic. There are two writer implementations: CLI and JSON. This made the dumper itself much more readable and maintanable sample output: ``` (lldb) thread trace dump instructions -t -a --id 100 -J [ { "id": 100, "tsc": "43591204528448966" "loadAddress": "0x407a91", "module": "a.out", "symbol": "void std::deque<Foo, std::allocator<Foo>>::_M_push_back_aux<Foo>(Foo&&)", "mnemonic": "movq", "source": "/usr/include/c++/8/bits/deque.tcc", "line": 492, "column": 30 }, ... ``` Differential Revision: https://reviews.llvm.org/D128316
2022-06-18 15:44:37 -07:00
prev_symbol_info = symbol_info;
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
}
[trace][intel pt] Support events A trace might contain events traced during the target's execution. For example, a thread might be paused for some period of time due to context switches or breakpoints, which actually force a context switch. Not only that, a trace might be paused because the CPU decides to trace only a specific part of the target, like the address filtering provided by intel pt, which will cause pause events. Besides this case, other kinds of events might exist. This patch adds the method `TraceCursor::GetEvents()`` that returns the list of events that happened right before the instruction being pointed at by the cursor. Some refactors were done to make this change simpler. Besides this new API, the instruction dumper now supports the -e flag which shows pause events, like in the following example, where pauses happened due to breakpoints. ``` thread #1: tid = 2717361 a.out`main + 20 at main.cpp:27:20 0: 0x00000000004023d9 leaq -0x1200(%rbp), %rax [paused] 1: 0x00000000004023e0 movq %rax, %rdi [paused] 2: 0x00000000004023e3 callq 0x403a62 ; std::vector<int, std::allocator<int> >::vector at stl_vector.h:391:7 a.out`std::vector<int, std::allocator<int> >::vector() at stl_vector.h:391:7 3: 0x0000000000403a62 pushq %rbp 4: 0x0000000000403a63 movq %rsp, %rbp ``` The `dump info` command has also been updated and now it shows the number of instructions that have associated events. Differential Revision: https://reviews.llvm.org/D123982
2022-04-18 09:28:10 -07:00
}
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
m_writer_up->TraceItem(item);
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
}
[trace] Improve the TraceCursor iteration API The current way ot traversing the cursor is a bit uncommon and it can't handle empty traces, in fact, its invariant is that it shold always point to a valid item. This diff simplifies the cursor API and allows it to point to invalid items, thus being able to handle empty traces or to know it ran out of data. - Removed all the granularity functionalities, because we are not actually making use of that. We can bring them back when they are actually needed. - change the looping logic to the following: ``` for (; cursor->HasValue(); cursor->Next()) { if (cursor->IsError()) { .. do something for error continue; } .. do something for instruction } ``` - added a HasValue method that can be used to identify if the cursor ran out of data, the trace is empty, or the user tried to move to an invalid position via SetId() or Seek() - made several simplifications to severals parts of the code. Differential Revision: https://reviews.llvm.org/D128543
2022-06-24 11:19:09 -07:00
if (!m_cursor_up->HasValue())
[trace] Make events first class items in the trace cursor and rework errors We want to include events with metadata, like context switches, and this requires the API to handle events with payloads (e.g. information about such context switches). Besides this, we want to support multiple similar events between two consecutive instructions, like multiple context switches. However, the current implementation is not good for this because we are defining events as bitmask enums associated with specific instructions. Thus, we need to decouple instructions from events and make events actual items in the trace, just like instructions and errors. - Add accessors in the TraceCursor to know if an item is an event or not - Modify from the TraceDumper all the way to DecodedThread to support - Renamed the paused event to disabled. - Improved the tsc handling logic. I was using an API for getting the tsc from libipt, but that was an overkill that should be used when not processing events manually, but as we are already processing events, we can more easily get the tscs. event items. Fortunately this simplified many things - As part of this refactor, I also fixed and long stating issue, which is that some non decoding errors were being inserted in the decoded thread. I changed this so that TraceIntelPT::Decode returns an error if the decoder couldn't be set up proplerly. Then, errors within a trace are actual anomalies found in between instrutions. All test pass Differential Revision: https://reviews.llvm.org/D128576
2022-06-24 14:02:47 -07:00
m_writer_up->NoMoreData();
[trace][intelpt] Introduce instruction Ids In order to support quick arbitrary access to instructions in the trace, we need each instruction to have an id. It could be an index or any other value that the trace plugin defines. This will be useful for reverse debugging or for creating callstacks, as each frame will need an instruction id associated with them. I've updated the `thread trace dump instructions` command accordingly. It now prints the instruction id instead of relative offset. I've also added a new --id argument that allows starting the dump from an arbitrary position. Differential Revision: https://reviews.llvm.org/D122254
2022-03-22 09:18:53 -07:00
return last_id;
[trace][intel pt] Implement the Intel PT cursor D104422 added the interface for TraceCursor, which is the main way to traverse instructions in a trace. This diff implements the corresponding cursor class for Intel PT and deletes the now obsolete code. Besides that, the logic for the "thread trace dump instructions" was adapted to use this cursor (pretty much I ended up moving code from Trace.cpp to TraceCursor.cpp). The command by default traverses the instructions backwards, and if the user passes --forwards, then it's not forwards. More information about that is in the Options.td file. Regarding the Intel PT cursor. All Intel PT cursors for the same thread share the same DecodedThread instance. I'm not yet implementing lazy decoding because we don't need it. That'll be for later. For the time being, the entire thread trace is decoded when the first cursor for that thread is requested. Differential Revision: https://reviews.llvm.org/D105531
2021-06-29 14:03:30 -07:00
}
Reference in New Issue Copy Permalink