i#6751 trace_entry_t: pretty printer #6771

edeiana · 2024-04-11T01:25:29Z

A sequence of trace_entry_t records is what we use for on-disk representation of traces.
To keep traces compact, the fields in the trace_entry_t struct are overloaded
(i.e., they mean different things depending on the value of other fields in the struct).

We disambiguate this overloading with this "record_view" tool, which pretty prints
trace_entry_t records, explicitly stating the meaning of each field for a specific
trace_entry_t.
The tool pretty prints one trace_entry_t record per line to std::cerr.

It can be invoked with:
drrun -t drmemtrace -tool internal_record_view -infile path/to/trace.zip.
Note that -sim_refs/-skip_refs NUMBER to print/skip the first NUMBER of
trace_entry_t records is supported (useful for large traces).

To test the correctness of the printed values we compare them with the raw data using:
zcat path/to/trace.zip | od -A x -t x2 -w12 | awk '{printf "%s | %s %s %s%s%s%s\n", $1, $2, $3, $7, $6, $5, $4}'
as described here: https://dynamorio.org/page_debug_memtrace.html#autotoc_md136.

TODO: add unit tests (+ improve printing of marker values? + improve output formatting/spacing?).

Issue: #6751

Skeleton for record_view, a new tool to visualize trace_entry_t records. Currently it prints the type of all trace_entry_t in a trace. Issue #6751

Printing the type before was working by sheer luck, due to layout of trace_entry_t and memref_t struct.

clients/drcachesim/CMakeLists.txt

abhinav92003 · 2024-04-15T18:25:25Z

clients/drcachesim/common/trace_entry.cpp

@@ -88,5 +88,55 @@ const char *const trace_type_names[] = {
    "untaken_jump",
 };

+const char *const trace_version_names[] = {


Since for trace version the enum value matters, let's add the corresponding enum value too to these strings.

As in, for example: "trace_entry_version_no_kernel_pc" -> "trace_entry_version_no_kernel_pc_2" ? (2 is the enum value)
Although I'm not quite understanding why the enum value matters in the string representation of TRACE_ENTRY_VERSION_ enum. They have different names after all.
Unless you're referring to trace_version_names[0] (and [1]), which are "unknown"? If so, you mean I should just differentiate those 2?

Although I'm not quite understanding why the enum value matters in the string representation of TRACE_ENTRY_VERSION_ enum

I'm considering a use case where the user wants to know whether their trace has a version more recent than some other version (some of our tools want a minimum trace version). Having the enum value would be easier, but I guess the user can always look up the enum value themselves using just the enum string. So it's fine either way I guess.

Can we print the enum value along side the string?

Got it, I didn't understand that the enum value had a meaning (larger == more recent trace version?).
I like @xdje42 suggestion. Now printing it when we print the trace_entry_t record (but not including it in trace_version_names[]).

clients/drcachesim/common/trace_entry.cpp

abhinav92003 · 2024-04-15T18:27:42Z

clients/drcachesim/common/trace_entry.cpp

+    "trace_entry_version_frequent_timestamps",
+};
+
+const char *const trace_marker_names[] = {


Would we want the strings at clients/drcachesim/tools/view.cpp to be replaced by these? Maybe. Add a TODO at view.cpp.

That would change all the output recorded in the docs here and in the sample traces repo and in internal docs so would not be taken lightly.

The reverse might be an easier thing to do. See all the comments about sharing code: eliminate this array and use the existing public pretty-printer's marker printing code.

#6771 (comment)

The reverse might be an easier thing to do. See all the comments about sharing code: eliminate this array and use the existing public pretty-printer's marker printing code.

I modified this array to be consistent with view.cpp (which, now, view.cpp also uses).
I think we still want a simple string representation of a marker type, we don't want to get rid of this array.
What view.cpp does is merging together the string representation of a marker type + a marker value.

Now, trace_marker_names[] contains the string representation of marker types only, and it's used in the new trace_marker_type_value_as_string(), which returns a string representation of marker type + value (and it's, for the most part, in common between view.cpp and record_view.cpp).

abhinav92003 · 2024-04-15T18:37:39Z

clients/drcachesim/tools/record_view.cpp

+        uint pid = (uint)entry.addr;
+        std::cerr << trace_type_name << ", pid: " << pid << "\n";
+    } else if (trace_type == TRACE_TYPE_MARKER) {
+        /* XXX i#6751: we have a lot of different types of markers; we should use some


clients/drcachesim/tools/view.cpp already has an exhaustive switch-case. It can be shared with this tool.

Ok.
Although not all of it can be shared.
view.cpp does some delayed printing and extra processing, which would defeat the purpose of "record_view": we want one line per trace_entry_t to show the exact sequence of on-disk records, we don't want to do the extra processing of view.cpp, it should be a 1 to 1 "mirror" of the trace file, just human readable.

Now sharing (between view and record_view) the printing of all TRACE_MARKER_TYPE_ cases that do not require extra processing.

abhinav92003 · 2024-04-15T18:38:44Z

clients/drcachesim/tools/record_view.cpp

+            std::cerr << " " << instr_length;
+        }
+        std::cerr << "\n";
+    } else if (type_is_instr(trace_type)) {


clients/drcachesim/tools/view.cpp disambiguates various kinds of instrs. We should share that logic with this tool.

Mhm, view.cpp is actually just renaming trace_type_names[], which is weird, because every other tool uses trace_type_names[], but view.cpp does not.
Should we switch this around and have view.cpp use trace_type_names[]?
Or change trace_type_names[] with what view.cpp prints?
Or does this break too much documentation and/or other assumptions I'm not aware of?
(If we decide to go this way, the aforementioned changes should go in a separate PR IMHO).

abhinav92003 · 2024-04-15T18:39:11Z

clients/drcachesim/tools/record_view.cpp

+     * similar TRACE_TYPE_ together, otherwise we compare trace_type against one or two
+     * specific TRACE_TYPE_ directly.
+     */
+    if (trace_type == TRACE_TYPE_HEADER) {


We should try to share more code with clients/drcachesim/tools/view.cpp where possible; e.g. see other comments.

For sharing of TRACE_TYPE_ pretty printing between view.cpp and record_view.cpp we need to come to a decision for what is the right way to print TRACE_TYPE_ enum values.
Right now there are two string representations: one hardcoded in view.cpp and one in trace_type_names[] (used by other tools).
#6771 (comment)

clients/drcachesim/tools/record_view_create.h

abhinav92003 · 2024-04-15T18:40:19Z

clients/drcachesim/CMakeLists.txt

@@ -165,13 +165,15 @@ add_exported_library(drmemtrace_opcode_mix STATIC tools/opcode_mix.cpp)
 add_exported_library(drmemtrace_syscall_mix STATIC tools/syscall_mix.cpp)
 add_exported_library(drmemtrace_view STATIC tools/view.cpp)


Please add a unit test similar to clients/drcachesim/tests/view_test.cpp.

Also some test that verifies the output for some checked in raw trace (e.g. clients/drcachesim/tests/drmemtrace.threadsig.aarch64.raw/raw) like clients/drcachesim/tests/offline-view.templatex.

Yes, that's in the TODO (see PR description).
However, before working on that, I'd like to come to a consensus on the pretty printed output of internal_record_view (<--- new tool name), as that is what I will test against.

Here's what it prints now (a short "representative" snippet, note that I OMITTED a few things because I wasn't sure I could share them here... the actual output has those values):

The internal_record_view tool is a pretty printer for trace_entry_t records. The trace_entry_t internal record format is not a public interface and is subject to change without notice. This tool is meant for debugging only, please do not rely on the details here. <header, trace_version: 6 == frequent_timestamps> <marker: version 6 frequent_timestamps> <marker: filetype 0xe40 x86_64> <thread, tid: 259013> <pid, pid: 259013> <marker: cache line size OMITTED> <marker: chunk instruction count 10000000> <marker: page size OMITTED> <marker: timestamp 13352585958813850> <marker: cpu id 3> <encoding, num_encoding_bytes: 8, encoding_bytes: OMITTED> <instr, length: 8, pc: 0x7f6fdd3ec360> <encoding, num_encoding_bytes: 8, encoding_bytes: OMITTED> <direct_call, length: 8, pc: 0x7f6fdd3ec368> <write, memref_size: 8, memref_addr: 0x7fffa4ef43c8> <encoding, num_encoding_bytes: 8, encoding_bytes: OMITTED> <instr, length: 8, pc: 0x7f6fdd3ec370> <write, memref_size: 8, memref_addr: 0x7fffa4ef43c0> ...

Is it acceptable? Do we need "--------" dividers? A header at the top? Do we want to number each line? Tabs?
I'm fine with how it looks now, just wondering.

I don't think it's worth spending any more time on this (esp for things like dividers and ordinals that the main view tool already has): this PR is just adding an internal tool that honestly will likely be rarely used, as evidenced by it not being needed in the past. Even now there likely is no use case where you wouldn't also go run the final view tool afterward, since that's the real view seen by tools. E.g., for your own ISA transform and filtering, you can't just go by the output of this record view tool: you have to make sure it works at the memref_t layer, so you have to use the real view tool plus invariant checks anyway. This internal tool is only a limited-use debugging step pretty much always followed up by using the "real" pretty printer.

Thinking more about when I've looked at the on-disk view with od: the most recent was debugging record_filter zip chunking support. There I had to look just before and after the 10M-instr chunk boundaries. Running od on one particular zipfile subfile at a time made this very easy. Looking at the output above with no ordinals, and having to pass in the whole trace file/dir at once: how would I focus on chunk boundaries? I might end up going back to od! I guess -skip_instructions is technically implemented for record_reader_t? But it's slow: the fast chunk skips are not implemented. Plus if the record_filter being debugged got the chunk boundary wrong I would have to go search for the chunk ord marker; if that's missing or wrong: would have to fall back to od.

Not sure there's an action item here: just an observation that this new tool is not enough to debug all on-disk issues as it abstracts away the file splits and I'm not sure it would have been useful the last time I did that. Adding ordinals would help -- but I don't know it's worth the effort. I would probably go run the regular view tool skipped to the chunk transition and take the closest timestamps and search for that in this tool's output or sthg. But I would again want to be at the real file layer instead of the trace_entry_t stream layer's abstracting away of the file divisions.

derekbruening

I have mixed feelings about adding this tool: part of me does not want to add it as we do not want to encourage users to create tools that operate on the trace_entry_t format. We consider that format subject to change and to not be a public interface. It has once-only data that requires caching that easily leads to errors if users operate on it. We have already seen external converters such as a champsim converter prototype incorrectly use this format.

clients/drcachesim/common/options.h

derekbruening · 2024-04-15T19:15:38Z

clients/drcachesim/tools/record_view.h

+namespace dynamorio {
+namespace drmemtrace {
+
+/**


I have mixed feelings about adding this tool: part of me does not want to add it as we do not want to encourage users to create tools that operate on the trace_entry_t format. We consider that format subject to change and to not be a public interface. It has once-only data that requires caching that easily leads to errors if users operate on it. We have already seen external converters such as a champsim converter prototype incorrectly use this format.

What I'm getting as is should this have Doxygen comments for public docs?

Oh, I thought tools that operate on trace_entry_t were considered "public" for some reason (i.e., same "visibility" of tools operating on memref_t).
My vote is for giving "record_view" the same visibility as "record_filter" (which is also a tool that operates on trace_entry_t).
"record_filter" has doxygen comments for public docs, so I followed the same for "record_view".

If tools that operate on trace_entry_t are not supposed to be public, then we should remove the public documentation for all of them and transform doxygen comments in regular comments.
(Separate PR for "record_filter"?)

No, trace_entry_t is not meant to be a public interface with guaranteed stability. The public interface is the memref_t record and reader library and the libraries on top of those like the analysis tools. trace_entry_t is supposed to be treated more like a black box by users. Its individual fields are not doxygen-commented.

Hence, providing a pretty printer seems to send the wrong message, encouraging users to peer inside the black box. We would prefer things like converters to other simulator formats to use memref_t + reader_t whose abstraction layer hides a number of messy details.

The record_filter tool can be used while keeping trace_entry_t a black box, as basically all of its filters operate above the memref_t abstraction level: remove marker types; trim to timestamp values; apply cache filters. So it is different from a trace_entry_t pretty printer.

What are the use cases of the record_view tool? The one I had in mind was debugging invariant errors in the raw trace. But that is likely more a trace-dev use case, rather than for trace users.

The one I had in mind was debugging invariant errors in the raw trace.

You mean the underlying trace_entry_t file on disk and not the offline "raw" un-pre-processed files, right?

Along that line of thought: I would see a trace_entry_t pretty-printer along the same lines as a raw pretty-printer: used only by trace-internal devs and not by any trace gatherers/users.

You mean the underlying trace_entry_t file on disk and not the offline "raw" un-pre-processed files, right?

Well both can be useful for debugging invariant errors. I agree that both are internal use cases. But does that mean we shouldn't add the record_view at all? Or maybe just make it a separate executable that's visibly marked internal (instead of supporting -simulator_type record_view).

Making it clear it's internal seems best; maybe even in the name: undocumented publicly, but can trigger via -simulator_type internal_record_view. And it prints a header every time saying "The internal record format is not a public interface and is subject to change without notice; meant for debugging only; please do not rely on the details here" or somesuch.

Adding "internal" to the name SGTM.

Ok, I think the final decision here is to add the "warning header" (done) and renaming record_view to internal_record_view (done).

derekbruening · 2024-04-15T19:16:50Z

clients/drcachesim/tools/record_view.cpp

+        unsigned short num_encoding_bytes = entry.size;
+        std::cerr << trace_type_name << ", num_encoding_bytes: " << num_encoding_bytes
+                  << ", encoding_bytes: 0x" << std::hex;
+        /* Print encoding byte by byte (little-endian).


This is not how encodings should be printed for AArch{32,64}.

clients/drcachesim/tools/record_view.h

derekbruening · 2024-04-24T18:50:16Z

clients/drcachesim/CMakeLists.txt

@@ -165,13 +165,15 @@ add_exported_library(drmemtrace_opcode_mix STATIC tools/opcode_mix.cpp)
 add_exported_library(drmemtrace_syscall_mix STATIC tools/syscall_mix.cpp)


To test the correctness of the printed values we compare them with the raw data using:
zcat path/to/trace.zip | od -A x -t x2 -w12 | awk '{printf "%s | %s %s %s%s%s%s\n", $1, $2, $3, $7, $6, $5, $4}'
as described here: https://dynamorio.org/page_debug_memtrace.html#autotoc_md136.

That page should be updated to point at this new tool, but please leave the od commands: as noted below some on-disk-format debugging needs to be at the real file level and not the trace_entry_t-stream level.

derekbruening · 2024-04-24T19:03:34Z

clients/drcachesim/CMakeLists.txt

@@ -165,13 +165,15 @@ add_exported_library(drmemtrace_opcode_mix STATIC tools/opcode_mix.cpp)
 add_exported_library(drmemtrace_syscall_mix STATIC tools/syscall_mix.cpp)
 add_exported_library(drmemtrace_view STATIC tools/view.cpp)


Thinking more about when I've looked at the on-disk view with od: the most recent was debugging record_filter zip chunking support. There I had to look just before and after the 10M-instr chunk boundaries. Running od on one particular zipfile subfile at a time made this very easy. Looking at the output above with no ordinals, and having to pass in the whole trace file/dir at once: how would I focus on chunk boundaries? I might end up going back to od! I guess -skip_instructions is technically implemented for record_reader_t? But it's slow: the fast chunk skips are not implemented. Plus if the record_filter being debugged got the chunk boundary wrong I would have to go search for the chunk ord marker; if that's missing or wrong: would have to fall back to od.

Not sure there's an action item here: just an observation that this new tool is not enough to debug all on-disk issues as it abstracts away the file splits and I'm not sure it would have been useful the last time I did that. Adding ordinals would help -- but I don't know it's worth the effort. I would probably go run the regular view tool skipped to the chunk transition and take the closest timestamps and search for that in this tool's output or sthg. But I would again want to be at the real file layer instead of the trace_entry_t stream layer's abstracting away of the file divisions.

derekbruening · 2024-04-24T19:15:23Z

clients/drcachesim/common/trace_entry.h

+        ss << "<" << marker_name << " type " << marker_value << ">\n";
+        break;
+    /* We don't have a way to know the trace version here.  This might be an offset,
+     * but we don't make any distinction.


Please elaborate as a new reader will have no idea what you mean: I only know b/c I remember a legacy version having offset instead of abs addr.

derekbruening · 2024-04-24T19:19:25Z

clients/drcachesim/launcher.cpp

@@ -323,7 +323,8 @@ _tmain(int argc, const TCHAR *targv[])
            FATAL_ERROR("invalid -outdir %s", op_outdir.get_value().c_str());
        }
    } else {
-        if (op_simulator_type.get_value() == RECORD_FILTER) {
+        if (op_simulator_type.get_value() == RECORD_FILTER ||
+            op_simulator_type.get_value() == INTERNAL_RECORD_VIEW) {


Do we need the multi-simulator support (colon-separated for memref_t tools) now that we have more than one tool? Add a XXX comment acknowledging we're aware multi-tool is not currently supported for record tools.

derekbruening · 2024-04-24T19:22:17Z

clients/drcachesim/tools/internal_record_view.cpp

+        std::cerr << "<" << trace_type_name
+                  << ", num_encoding_bytes: " << num_encoding_bytes
+                  << ", encoding_bytes: 0x" << std::hex;
+        /* Print encoding byte by byte (little-endian).


Byte-by-byte is only desirable for x86; we'd want words for AArch64, words or half-words (presumably we have LSB 1 for Thumb) for AArch32, and words for RISCV.

derekbruening · 2024-04-24T19:25:38Z

clients/drcachesim/tools/view.cpp

-            std::cerr << "<marker: trace end for context switch type "
+        case TRACE_MARKER_TYPE_SPLIT_VALUE:
+        case TRACE_MARKER_TYPE_SYSCALL_IDX:
+            std::cerr << "<marker: type " << memref.marker.marker_type << "; value "


Seems like these 2 cases can be omitted as this is the default behavior in the marker printing helper called below.

We actually catch those two cases in trace_marker_type_value_as_string() and print a more informative output that looks different than the one here: <marker: type NUM; value NUM>.
So, to preserve the previous view.cpp behavior, we catch these 2 cases early and print them the same way view.cpp used to print them. (I should have added a code-review comment about this, I forgot)

We can remove these two cases if:

we decide we don't care about printing a more informative output (hence we remove them from here and trace_marker_type_value_as_string(), letting the default in trace_marker_type_value_as_string() take care of it. (<--- not a fan of this, I think we should print the most "informative" version of marker type and value)

we decide to update view.cpp's printing for those two cases and align it to trace_marker_type_value_as_string(). (<--- might break doc and examples?)

SPLIT_VALUE will never be seen by view.cpp as it is never presented as a memref_t, so there is no reason to have an explicit case entry for it.

Anything not explicitly in a case statement in view.cpp can be considered to not matter: if someone wanted to see that marker we would add a case statement. The default there is a fallback and we do not need to preserve it: we don't want to preserve it: we want to print the string name, not the marker enum number.

Got it.
Then, since those two cases were both catched in what used to be view.cpp's default case, we can remove them and let trace_marker_type_value_as_string() print them (even though view.cpp will never see SPLIT_VALUE).
Going with 2).

derekbruening · 2024-04-24T19:26:47Z

clients/drcachesim/tools/view.cpp

+             * bookkeeping.
+             */
+            std::cerr << trace_marker_type_value_as_string(memref.marker.marker_type,
+                                                           memref.marker.marker_value);
            break;
        }
        return true;


Please add a unit test. (This may be a dup of another comment thread.)

edeiana added 6 commits April 10, 2024 18:20

i#6751 trace_entry_t: pretty printer

b48eed0

Skeleton for record_view, a new tool to visualize trace_entry_t records. Currently it prints the type of all trace_entry_t in a trace. Issue #6751

Added -sim_refs support to print only the first sim_refs records.

20db00b

Added record_view to record_analysis_tool_t tool launcher.

dd80234

Printing the type before was working by sheer luck, due to layout of trace_entry_t and memref_t struct.

Printing all info, although printing of markers can be improved.

b10b1a2

Tentative fix for windows build.

00eefa0

Merge branch 'master' into i6751-trace_entry_t-pp

8788d3b

edeiana marked this pull request as ready for review April 13, 2024 03:52

edeiana requested review from xdje42 and abhinav92003 April 13, 2024 04:03

abhinav92003 requested changes Apr 15, 2024

View reviewed changes

derekbruening reviewed Apr 15, 2024

View reviewed changes

edeiana added 2 commits April 18, 2024 11:27

Added skip_refs functionality.

793f6a4

Fixed comment typo: std::err -> std::cerr.

c7881a6

derekbruening mentioned this pull request Apr 19, 2024

Pretty printer for #trace_entry_t-format traces #6751

Open

edeiana added 7 commits April 19, 2024 20:24

Added string representation of TRACE_MARKER_TYPE_RESERVED_END.

b3a3d38

Improved names for string representation of enums.

2af0d67

Now sharing code with view.cpp when printing markers.

8b1ef16

Now invoking record_view with internal_record_view.

73f8295

Added description to trace_marker_type_value_as_string().

58c6032

Added warning header.

cdb3eaa

simple simply. ugh.

612a8ea

derekbruening reviewed Apr 24, 2024

View reviewed changes

clients/drcachesim/tools/record_view.h Outdated Show resolved Hide resolved

edeiana added 2 commits April 23, 2024 23:55

Renaming: record_view to internal_record_view.

81e6b24

Code cleanup. Better comments.

81ff649

edeiana requested review from abhinav92003 and derekbruening April 24, 2024 07:11

Fixed formatting.

c940f18

derekbruening reviewed Apr 24, 2024

View reviewed changes

edeiana added 2 commits October 22, 2024 15:19

Merge remote-tracking branch 'origin/master' into i6751-trace_entry_t-pp

5390027

Minor post-merge fixes.

7baee4e

		@@ -165,13 +165,15 @@ add_exported_library(drmemtrace_opcode_mix STATIC tools/opcode_mix.cpp)
		add_exported_library(drmemtrace_syscall_mix STATIC tools/syscall_mix.cpp)
		add_exported_library(drmemtrace_view STATIC tools/view.cpp)

i#6751 trace_entry_t: pretty printer #6771

Are you sure you want to change the base?

i#6751 trace_entry_t: pretty printer #6771

Conversation

edeiana commented Apr 11, 2024 • edited Loading

Choose a reason for hiding this comment

edeiana Apr 18, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edeiana Apr 24, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edeiana Apr 18, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edeiana Apr 24, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edeiana Apr 24, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

derekbruening left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edeiana Apr 18, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

abhinav92003 Apr 19, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edeiana Apr 24, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

edeiana commented Apr 11, 2024 •

edited

Loading

edeiana Apr 18, 2024 •

edited

Loading

edeiana Apr 24, 2024 •

edited

Loading

edeiana Apr 18, 2024 •

edited

Loading

edeiana Apr 24, 2024 •

edited

Loading

edeiana Apr 24, 2024 •

edited

Loading

edeiana Apr 18, 2024 •

edited

Loading

abhinav92003 Apr 19, 2024 •

edited

Loading

edeiana Apr 24, 2024 •

edited

Loading