Skip to content

Commit

Permalink
docs: Update trace analysis page with student feedback
Browse files Browse the repository at this point in the history
  • Loading branch information
@colluca
colluca committed Jun 17, 2024
1 parent 9e61160 commit 1965ed0
Showing 1 changed file with 43 additions and 11 deletions.
54 changes: 43 additions & 11 deletions docs/ug/trace_analysis.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,24 +24,56 @@ Here is an extract of a trace generated by the previous script:
1160000 1131 M 0x80000254 add a0, a5, a2 #; a5 = 0x10000c00, a2 = 0, (wrb) a0 <-- 0x10000c00
1161000 1132 M 0x80000258 scfgwi a0, 769 #; a0 = 0x10000c00
1162000 1133 M 0x8000025c auipc a0, 0x5 #; (wrb) a0 <-- 0x8000525c
1164000 1135 M 0x80000260 addi a0, a0, -1396 #; a0 = 0x8000525c, (wrb) a0 <-- 0x80004ce8
1166000 1137 M 0x80000268 add a0, a6, a2 #; a6 = 0x10001800, a2 = 0, (wrb) a0 <-- 0x10001800
1167000 1138 M 0x8000026c scfgwi a0, 898 #; a0 = 0x10001800
1163000 1134 M 0x80000260 addi a0, a0, -1396 #; a0 = 0x8000525c, (wrb) a0 <-- 0x80004ce8
1165000 1136 M 0x80000268 add a0, a6, a2 #; a6 = 0x10001800, a2 = 0, (wrb) a0 <-- 0x10001800
1166000 1137 M 0x8000026c scfgwi a0, 898 #; a0 = 0x10001800
M 0x80000264 fld ft3, 0(a0) #; ft3 <~~ Doub[0x80004ce8]
1169000 1140 M 0x80000270 csrsi ssr, 1 #;
1170000 1141 M 0x80000274 frep 48, 1 #; outer, 48 issues
1177000 1148 M #; (f:lsu) ft3 <-- -32.7504962
1168000 1139 M 0x80000270 csrsi ssr, 1 #;
1169000 1140 M 0x80000274 frep 48, 1 #; outer, 48 issues
1176000 1147 M #; (f:lsu) ft3 <-- -32.7504962
```

From left to right, the columns contain the following information: simulation time (in picoseconds), CPU cycle, privilege mode, program counter (or memory address of the current instruction), instruction mnemonic, instruction arguments, a comment block reporting additional information.

We will now break down the previous trace and understand what is going on piece by piece.

```
1147000 1118 M 0x8000022c li a1, 47 #; (wrb) a1 <-- 47
1148000 1119 M 0x80000230 scfgwi a1, 64 #; a1 = 47
1149000 1120 M 0x80000234 scfgwi a3, 192 #; a3 = 8
1150000 1121 M 0x80000238 scfgwi a1, 65 #; a1 = 47
1151000 1122 M 0x8000023c scfgwi a3, 193 #; a3 = 8
1152000 1123 M 0x80000240 scfgwi a1, 66 #; a1 = 47
1153000 1124 M 0x80000244 scfgwi a3, 194 #; a3 = 8
```

Snitch is a single-issue single-stage in-order core implementing the RV32I instruction set. Instructions are fetched in order and complete in a single cycle. As can be seen from cycle 1118 to 1124, all instructions execute in a single cycle, and the program counter increases regularly in steps of 4 bytes (all instructions are 32-bit wide). The comment on line 1118 `(wrb) a1 <-- 47` tells us that in that same cycle, where the `li` instruction is issued and executed, the core also writes back (`wrb`) a value of `47` to destination register `a1`, as a result of that instruction. The comments on lines 1119 to 1124 report the values of the source registers involved in the respective instructions at the time they are issued.

Additional instructions are supported by means of accelerators connected to Snitch's accelerator interface. When Snitch fetches and decodes an instruction which is supported through one of the accelerators, it offloads the instruction to the corresponding accelerator. This is the case for instructions in the RISC-V "M" extension, which are supported through an external MULDIV unit, shared by all cores in a Snitch cluster. Offloaded instructions need to travel a longer distance to reach the dedicated functional unit, and may be pipelined. To tolerate this latency, the Snitch core may fetch, issue and execute successive instructions even before the offloaded instruction commits its result to the register file. Only instructions which do not have RAW or WAW dependencies with any outstanding offloaded instruction are allowed to execute. As an example, at cycle 1125 Snitch issues the `mul` instruction, which is offloaded to the shared MULDIV unit. The next trace line skips three cycles, as Snitch is stalled waiting for the result of the `mul`. Indeed, if you peek at line 1129, you can see the next instruction presents a RAW dependency on the previous instruction through register `a2`. The trace line at 1128 is also unique in that it does not contain any instruction. In fact, no instruction can be issued yet, but the comment informs us that the accelerator interface (`acc`) is writing back a value of `0` to register `a2`. Therefore, in the next cycle the `add` instruction can read the content of register `a2`, which reflects the value written in the previous cycle.
```
1154000 1125 M 0x80000248 mul a2, a2, a7 #; a2 = 0, a7 = 384
1157000 1128 M #; (acc) a2 <-- 0
1158000 1129 M 0x8000024c add a0, a0, a2 #; a0 = 0x10000000, a2 = 0, (wrb) a0 <-- 0x10000000
```

Additional instructions are supported by means of accelerators connected to Snitch's accelerator interface. When Snitch fetches and decodes an instruction which is supported through one of the accelerators, it offloads the instruction to the corresponding accelerator. This is the case for instructions in the RISC-V "M" Standard Extension for Integer Multiplication and Division, which are supported through an external MULDIV unit, shared by all cores in a Snitch cluster. Offloaded instructions need to travel a longer distance to reach the dedicated functional unit, and may be pipelined. To tolerate this latency, the Snitch core may fetch, issue and execute successive instructions even before the offloaded instruction commits its result to the register file. Only instructions which do not have RAW or WAW dependencies with any outstanding offloaded instruction are allowed to execute. As an example, at cycle 1125 Snitch issues the `mul` instruction, which is offloaded to the shared MULDIV unit. The next trace line skips three cycles, as Snitch is stalled waiting for the result of the `mul`. Indeed, if you peek at line 1129, you can see the next instruction presents a RAW dependency on the previous instruction through register `a2`. The trace line at 1128 is also unique in that it does not contain any instruction. In fact, no instruction can be issued yet, but the comment informs us that the accelerator interface (`acc`) is writing back a value of `0` to register `a2`. Therefore, in the next cycle the `add` instruction can read the content of register `a2`, which reflects the value written in the previous cycle.

```
1159000 1130 M 0x80000250 scfgwi a0, 768 #; a0 = 0x10000000
1160000 1131 M 0x80000254 add a0, a5, a2 #; a5 = 0x10000c00, a2 = 0, (wrb) a0 <-- 0x10000c00
1161000 1132 M 0x80000258 scfgwi a0, 769 #; a0 = 0x10000c00
1162000 1133 M 0x8000025c auipc a0, 0x5 #; (wrb) a0 <-- 0x8000525c
1163000 1134 M 0x80000260 addi a0, a0, -1396 #; a0 = 0x8000525c, (wrb) a0 <-- 0x80004ce8
1165000 1136 M 0x80000268 add a0, a6, a2 #; a6 = 0x10001800, a2 = 0, (wrb) a0 <-- 0x10001800
1166000 1137 M 0x8000026c scfgwi a0, 898 #; a0 = 0x10001800
M 0x80000264 fld ft3, 0(a0) #; ft3 <~~ Doub[0x80004ce8]
1168000 1139 M 0x80000270 csrsi ssr, 1 #;
1169000 1140 M 0x80000274 frep 48, 1 #; outer, 48 issues
1176000 1147 M #; (f:lsu) ft3 <-- -32.7504962
```

All proceeds regularly up to cycle 1137. Here we observe a jump in the program counter, which is not justified by a branch or other control-flow instruction. At the same time, we can observe a lost cycle between this and the previous instruction. What happened? As mentioned earlier, instructions are fetched and issued in order. We would therefore expect instruction `0x80000264` to be issued at cycle 1136. If we peek a little bit further in the trace, we find the "missing" instruction reported in cycle 1138. This delay is explained by the fact that the RISC-V "D" extension is also implemented by an accelerator: the FPU subsystem (FPSS) which, differently from the integer MULDIV unit, is private to each core and located in the core complex. Differently from the offloading instance at cycle 1125, here the two successive instructions are allowed to execute before the offloaded instruction completes, since they do not have any dependency on the previous instruction. When, in cycle 1138, the `fld` instruction is issued in the FPSS, the `scfgwi` instruction is simultaneously issued in the base Snitch core. This should not be seen as to contradict our assumption that Snitch is a single-issue core, as the `fld` instruction was indeed issued by Snitch in cycle 1136, whereas in cycle 1138 it issues the `scfgwi` instruction alone. Hence, it can only occur that two instructions execute simultaneously in the trace if a cycle was lost in advance.
All proceeds regularly up to cycle 1136. Here we observe a jump in the program counter, which is not justified by a branch or other control-flow instruction. At the same time, we can observe a lost cycle between this and the previous instruction. What happened? As mentioned earlier, instructions are fetched and issued in order. We would therefore expect instruction `0x80000264` to be issued at cycle 1135. If we peek a little bit further in the trace, we find the "missing" instruction reported in cycle 1137. This delay is explained by the fact that the RISC-V "D" Standard Extension for Double-Precision Floating-Point is also implemented by an accelerator: the FPU subsystem (FPSS) which, differently from the integer MULDIV unit, is private to each core and located in the core complex. Differently from the offloading instance at cycle 1125, here the two successive instructions are allowed to execute before the offloaded instruction completes, since they do not have any dependency on the previous instruction. When, in cycle 1137, the `fld` instruction is issued in the FPSS, the `scfgwi` instruction is simultaneously issued in the base Snitch core. This should not be seen as to contradict our assumption that Snitch is a single-issue core, as the `fld` instruction was indeed issued by Snitch in cycle 1135, whereas in cycle 1137 it issues the `scfgwi` instruction alone. Hence, it can only occur that two instructions execute simultaneously in the trace if a cycle was lost in advance.

Note that the comment next to the `fld` instruction uses a similar syntax to the one we previously encountered for writebacks, with the difference that 1) it presents a "wavy" arrow, 2) the agent of the writeback is not specified and 3) on the right-hand side of the arrow we don't have a numerical value but a memory address. This notation informs us that a load from that memory address has been initiated, but the corresponding writeback only occurs on line 1148. The agent of the writeback in this case is the floating-point LSU (`f:lsu`). The value of the source register `a0` is omitted in the comment on line 1138, as it can be easily recovered from the memory address and the offset in the instruction arguments. If you were particularly careful, the last value which was written back to `a0` was `0x10001800` on line 1137, so why does it now evaluate to `0x80004ce8`? The reason is, once again, that the `fld` was actually issued in cycle 1136, and thus observes the value which was then last written back (`0x80004ce8` on line 1135), in accordance with the original program order.
Note that the comment next to the `fld` instruction uses a similar syntax to the one we previously encountered for writebacks, with the difference that 1) it presents a "wavy" arrow, 2) the agent of the writeback is not specified and 3) on the right-hand side of the arrow we don't have a numerical value but a memory address. This notation informs us that a load from that memory address has been initiated, but the corresponding writeback only occurs on line 1147. The agent of the writeback in this case is the floating-point LSU (`f:lsu`). The value of the source register `a0` is omitted in the comment on line 1138, as it can be easily recovered from the memory address and the offset in the instruction arguments. If you were particularly careful, the last value which was written back to `a0` was `0x10001800` on line 1137, so why does it now evaluate to `0x80004ce8`? The reason is, once again, that the `fld` was actually issued in cycle 1136, and thus observes the value which was then last written back (`0x80004ce8` on line 1135), in accordance with the original program order.

One last note should be made about `frep` loops. While not visible from this trace, under `frep` operation Snitch becomes a pseudo-dual issue processor, i.e. instructions can be issued by the Snitch core, while the FREP sequencer repeatedly issues floating-point instructions. It is possible in this situation to consistently observe the core execute two instructions per cycle in the trace. The sequencer however does not have its own instruction fetch unit, but only a buffer where it caches loop body instructions, to fetch and issue these instructions from. The Snitch core must issue these instructions for the first loop iteration, when they will also be cached in the FREP sequencer, and only from the second iteration can the FREP sequencer operate independently. Thus, to observe the pseudo-dual issue behaviour, you must make sure in your code that the `frep` loop appears before any other operation you want to overlap with it in program order.

Expand Down Expand Up @@ -72,8 +104,8 @@ cycles 87
total_ipc 0.8046
```

These performance metrics can also be dumped to a JSON file for further processing (see [gen_trace.py](../../util/trace/gen_trace.py)).
A detailed description of each of the performance metrics follows:
The trace will contain the most relevant performance metrics for manual inspection. These and additional performance metrics can also be dumped to a JSON file for further processing (see [gen_trace.py](../../util/trace/gen_trace.py)).
In the following table you can find a complete list of all the performance metrics extracted from the trace along with their description:

|Metric |Description |
|--------------------------|----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
Expand Down

0 comments on commit 1965ed0

Please sign in to comment.