djsundog/circuitpython
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Add heap analysis scripts based on GDB breakpoint logs.

Browse Source
This commit is contained in:
Scott Shawcroft 2016-11-23 17:31:53 -08:00
parent ea1320bee7
commit a8fbad5d8b
5 changed files with 485 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

28
py/gc.c
View File

@ -102,6 +102,15 @@
#define GC_EXIT() #define GC_EXIT()
#endif #endif
#ifdef LOG_HEAP_ACTIVITY
volatile uint32_t change_me;
void __attribute__ ((noinline)) gc_log_change(uint32_t start_block, uint32_t length) {
change_me += start_block;
change_me += length; // Break on this line.
}
#endif
// TODO waste less memory; currently requires that all entries in alloc_table have a corresponding block in pool // TODO waste less memory; currently requires that all entries in alloc_table have a corresponding block in pool
void gc_init(void *start, void *end) { void gc_init(void *start, void *end) {
// align end pointer on block boundary // align end pointer on block boundary
@ -278,6 +287,10 @@ STATIC void gc_sweep(void) {
#endif #endif
free_tail = 1; free_tail = 1;
DEBUG_printf("gc_sweep(%x)\n", PTR_FROM_BLOCK(block)); DEBUG_printf("gc_sweep(%x)\n", PTR_FROM_BLOCK(block));
#ifdef LOG_HEAP_ACTIVITY
gc_log_change(block, 0);
#endif
#if MICROPY_PY_GC_COLLECT_RETVAL #if MICROPY_PY_GC_COLLECT_RETVAL
MP_STATE_MEM(gc_collected)++; MP_STATE_MEM(gc_collected)++;
#endif #endif
@ -470,6 +483,10 @@ found:
MP_STATE_MEM(gc_last_free_atb_index) = (i + 1) / BLOCKS_PER_ATB; MP_STATE_MEM(gc_last_free_atb_index) = (i + 1) / BLOCKS_PER_ATB;
} }
#ifdef LOG_HEAP_ACTIVITY
gc_log_change(start_block, end_block - start_block + 1);
#endif
// mark first block as used head // mark first block as used head
ATB_FREE_TO_HEAD(start_block); ATB_FREE_TO_HEAD(start_block);
@ -556,6 +573,9 @@ void gc_free(void *ptr) {
} }
// free head and all of its tail blocks // free head and all of its tail blocks
#ifdef LOG_HEAP_ACTIVITY
gc_log_change(block, 0);
#endif
do { do {
ATB_ANY_TO_FREE(block); ATB_ANY_TO_FREE(block);
block += 1; block += 1;
@ -715,6 +735,10 @@ void *gc_realloc(void *ptr_in, size_t n_bytes, bool allow_move) {
gc_dump_alloc_table(); gc_dump_alloc_table();
#endif #endif
#ifdef LOG_HEAP_ACTIVITY
gc_log_change(block, new_blocks);
#endif
return ptr_in; return ptr_in;
} }
@ -740,6 +764,10 @@ void *gc_realloc(void *ptr_in, size_t n_bytes, bool allow_move) {
gc_dump_alloc_table(); gc_dump_alloc_table();
#endif #endif
#ifdef LOG_HEAP_ACTIVITY
gc_log_change(block, new_blocks);
#endif
return ptr_in; return ptr_in;
} }

137
tools/gc_activity.html Normal file
View File

@ -0,0 +1,137 @@
<!DOCTYPE html>
<html>
<head>
<meta charset="utf-8">
<style>
html, body, svg {
margin: 0px;
min-height: 100%;
height: 100%;
width: 100%;
}
.chart rect {
fill: steelblue;
}
.axis text {
font: 10px sans-serif;
}
.axis path,
.axis line {
fill: none;
stroke: #000;
shape-rendering: crispEdges;
}
div.tooltip {
position: absolute;
# text-align: center;
# width: 60px;
# height: 28px;
padding: 2px;
font: 12px sans-serif;
background: lightsteelblue;
border: 0px;
}
</style>
</head>
<body>
<svg class="chart"></svg>
<script src="https://d3js.org/d3.v4.js"></script>
<script>
var barHeight = 2;
var chart = d3.select(".chart");
var margin = {top: 20, right: 30, bottom: 30, left: 40},
width = chart.style("width").replace("px", "") - margin.left - margin.right,
height = chart.style("height").replace("px", "") - margin.top - margin.bottom;
var x = d3.scaleLinear().range([0, width]);
var y = d3.scaleLinear().range([0, height]);
var chart = chart.append("g")
.attr("transform", "translate(" + margin.left + "," + margin.top + ")");
var xAxis = d3.axisBottom().scale(x);
var yAxis = d3.axisLeft().scale(y);
var div = d3.select("body").append("div")
.attr("class", "tooltip")
.style("opacity", 0);
d3.json("/allocation_history.json", function(error, data) {
console.log(data[0]);
x.domain([0, d3.max(data, function(d) { return d.end_time; })]);
y.domain([0, d3.max(data, function(d) { return d.start_block + d.size; })]);
chart.append("g")
.attr("class", "x axis")
.attr("transform", "translate(0," + height + ")")
.call(xAxis);
chart.append("g")
.attr("class", "y axis")
.call(yAxis);
var bar = chart.selectAll("g")
.data(data)
.enter().append("g")
.attr("transform", function(d, i) { return "translate(" + x(d.start_time) + "," + y(d.start_block) + ")"; });
bar.append("rect")
.attr("width", function(d) { return x(d.end_time - d.start_time); })
.attr("height", function(d) { return y(d.size) - 1; })
.on("mouseover", function(d) {
var trace = "";
for (var i = 0, len = d.start_trace.length; i < len; i++) {
var frame = d.start_trace[i];
trace += frame[2] + " " + frame[1] + "<br/>";
}
trace += "<br/>End Trace:<br/>";
for (var i = 0, len = d.end_trace.length; i < len; i++) {
var frame = d.end_trace[i];
trace += frame[2] + " " + frame[1] + "<br/>";
}
var side = "left";
var other_side = "right";
var pos_x = x(d.start_time) + margin.left;
if (width - pos_x < 300) {
side = "right";
other_side = "left";
pos_x = width - x(d.start_time) + margin.right;
}
var pos_y = (height - y(d.start_block) + margin.bottom)
var edge = "bottom";
var other_edge = "top";
if ((height - pos_y) < 300) {
edge = "top";
other_edge = "bottom";
pos_y = y(d.start_block) + margin.top + y(d.size);
}
div.style("opacity", 1)
.html("Start block: " + d.start_block + " Size: " + d.size + " blocks<br/><br/>" + trace)
.style(side, pos_x + "px")
.style(other_side, null)
.style(edge, pos_y + "px")
.style(other_edge, null);
});
// bar.append("text")
// .attr("x", function(d) { return x(d.value) - 3; })
// .attr("y", barHeight / 2)
// .attr("dy", ".35em")
// .text(function(d) { return d.value; });
});
function type(d) {
d.value = +d.value; // coerce to number
return d;
}
</script>
</body>
</html>

198
tools/gc_activity.md Normal file
View File

@ -0,0 +1,198 @@
# GC Analysis
Here are some terse instructions on doing heap analysis via gdb.
First, build your port with `LOG_HEAP_ACTIVITY` defined and load it onto your
board. This will enable calls to a gc log function that isn't inlined so it uses
only one breakpoint.
Next, double check that the `break gc.c:110` line in `output_gc_until_repl.txt`
has the correct line number. Also make sure the tar ext line connects to the
correct port. GDB is usually :3333 and JLink is :2331.
Now, run gdb from your port directory:
```
arm-none-eabi-gdb -x ../tools/output_gc_until_repl.txt build-metro_m0_flash/firmware.elf
```
This will take a little time while it breaks, backtraces and continues for every
gc change until the repl. At the end it will have a `mylog.txt` file.
To analyze that file run:
```
python3 ../tools/gc_activity.py mylog.txt
```
It will create a file `allocation_history.json` which documents the lifespan of
the allocations. It also outputs a tree of the current number of blocks
allocated by a piece of code such as:
```
main.c:298 main 5 blocks
main.c:159 reset_mp 2 blocks
../py/runtime.c:81 mp_init 2 blocks
../py/objmodule.c:227 mp_module_init 2 blocks
../py/objdict.c:595 mp_obj_dict_init 2 blocks
../py/map.c:79 mp_map_init 2 blocks
main.c:160 reset_mp 1 blocks
../py/objlist.c:458 mp_obj_list_init 1 blocks
main.c:164 reset_mp 1 blocks
../py/objlist.c:458 mp_obj_list_init 1 blocks
main.c:166 reset_mp 1 blocks
../py/objexcept.c:297 mp_obj_new_exception 1 blocks
../py/objexcept.c:307 mp_obj_new_exception_args 1 blocks
../py/objexcept.c:130 mp_obj_exception_make_new 1 blocks
main.c:311 main 289 blocks
main.c:211 start_mp 14 blocks
main.c:196 maybe_run 14 blocks
../lib/utils/pyexec.c:501 pyexec_file 14 blocks
main.c:352 mp_lexer_new_from_file 14 blocks
../py/../extmod/vfs_fat_lexer.c:80 fat_vfs_lexer_new_from_file 14 blocks
../py/qstr.c:184 qstr_from_str 14 blocks
../py/qstr.c:216 qstr_from_strn 8 blocks
../py/qstr.c:240 qstr_from_strn 6 blocks
../py/qstr.c:146 qstr_add 6 blocks
main.c:220 start_mp 275 blocks
main.c:196 maybe_run 275 blocks
../lib/utils/pyexec.c:508 pyexec_file 275 blocks
../lib/utils/pyexec.c:82 parse_compile_execute 4 blocks
../py/compile.c:3511 mp_compile 3 blocks
../py/compile.c:3451 mp_compile_to_raw_code 3 blocks
../py/compile.c:3092 compile_scope 3 blocks
../py/emitbc.c:419 mp_emit_bc_end_pass 3 blocks
../py/compile.c:3513 mp_compile 1 blocks
../py/emitglue.c:131 mp_make_function_from_raw_code 1 blocks
../py/objfun.c:364 mp_obj_new_fun_bc 1 blocks
../lib/utils/pyexec.c:88 parse_compile_execute 271 blocks
../py/runtime.c:551 mp_call_function_0 271 blocks
../py/runtime.c:577 mp_call_function_n_kw 271 blocks
../py/objfun.c:275 fun_bc_call 271 blocks
../py/vm.c:1161 mp_execute_bytecode 269 blocks
../py/runtime.c:1315 mp_import_name 269 blocks
../py/builtinimport.c:442 mp_builtin___import__ 2 blocks
../py/objmodule.c:113 mp_obj_new_module 1 blocks
../py/objmodule.c:115 mp_obj_new_module 1 blocks
../py/objdict.c:599 mp_obj_new_dict 1 blocks
../py/builtinimport.c:473 mp_builtin___import__ 267 blocks
../py/builtinimport.c:230 do_load 140 blocks
../py/emitglue.c:469 mp_raw_code_load_file 140 blocks
../py/emitglue.c:356 mp_raw_code_load 140 blocks
../py/emitglue.c:320 load_raw_code 8 blocks
../py/emitglue.c:295 load_bytecode_qstrs 8 blocks
../py/emitglue.c:265 load_qstr 8 blocks
../py/qstr.c:216 qstr_from_strn 8 blocks
../py/emitglue.c:331 load_raw_code 2 blocks
../py/emitglue.c:277 load_obj 1 blocks
../py/vstr.c:53 vstr_init_len 1 blocks
../py/vstr.c:46 vstr_init 1 blocks
../py/emitglue.c:280 load_obj 1 blocks
../py/objstr.c:2001 mp_obj_new_str_from_vstr 1 blocks
../py/emitglue.c:334 load_raw_code 130 blocks
../py/emitglue.c:306 load_raw_code 6 blocks
../py/emitglue.c:325 load_raw_code 4 blocks
../py/emitglue.c:328 load_raw_code 19 blocks
../py/emitglue.c:265 load_qstr 19 blocks
../py/qstr.c:216 qstr_from_strn 8 blocks
../py/qstr.c:240 qstr_from_strn 11 blocks
../py/qstr.c:146 qstr_add 11 blocks
../py/emitglue.c:334 load_raw_code 101 blocks
../py/emitglue.c:306 load_raw_code 80 blocks
../py/emitglue.c:320 load_raw_code 8 blocks
../py/emitglue.c:295 load_bytecode_qstrs 8 blocks
../py/emitglue.c:265 load_qstr 8 blocks
../py/qstr.c:216 qstr_from_strn 8 blocks
../py/emitglue.c:325 load_raw_code 13 blocks
../py/builtinimport.c:231 do_load 127 blocks
../py/builtinimport.c:181 do_execute_raw_code 127 blocks
../py/runtime.c:551 mp_call_function_0 127 blocks
../py/runtime.c:577 mp_call_function_n_kw 127 blocks
../py/objfun.c:275 fun_bc_call 127 blocks
../py/vm.c:400 mp_execute_bytecode 6 blocks
../py/runtime.c:168 mp_store_name 6 blocks
../py/objdict.c:612 mp_obj_dict_store 6 blocks
../py/map.c:283 mp_map_lookup 6 blocks
../py/map.c:130 mp_map_rehash 6 blocks
../py/vm.c:847 mp_execute_bytecode 2 blocks
../py/emitglue.c:131 mp_make_function_from_raw_code 2 blocks
../py/objfun.c:364 mp_obj_new_fun_bc 2 blocks
../py/vm.c:855 mp_execute_bytecode 3 blocks
../py/emitglue.c:131 mp_make_function_from_raw_code 3 blocks
../py/objfun.c:364 mp_obj_new_fun_bc 3 blocks
../py/vm.c:903 mp_execute_bytecode 110 blocks
../py/runtime.c:577 mp_call_function_n_kw 110 blocks
../py/objfun.c:129 fun_builtin_var_call 110 blocks
../py/modbuiltins.c:56 mp_builtin___build_class__ 5 blocks
../py/objdict.c:599 mp_obj_new_dict 5 blocks
../py/modbuiltins.c:60 mp_builtin___build_class__ 84 blocks
../py/runtime.c:551 mp_call_function_0 84 blocks
../py/runtime.c:577 mp_call_function_n_kw 84 blocks
../py/objfun.c:275 fun_bc_call 84 blocks
../py/vm.c:400 mp_execute_bytecode 17 blocks
../py/runtime.c:168 mp_store_name 17 blocks
../py/objdict.c:612 mp_obj_dict_store 17 blocks
../py/map.c:283 mp_map_lookup 17 blocks
../py/map.c:130 mp_map_rehash 17 blocks
../py/vm.c:847 mp_execute_bytecode 9 blocks
../py/emitglue.c:131 mp_make_function_from_raw_code 9 blocks
../py/objfun.c:364 mp_obj_new_fun_bc 9 blocks
../py/vm.c:855 mp_execute_bytecode 8 blocks
../py/emitglue.c:131 mp_make_function_from_raw_code 8 blocks
../py/objfun.c:364 mp_obj_new_fun_bc 8 blocks
../py/vm.c:903 mp_execute_bytecode 50 blocks
../py/runtime.c:577 mp_call_function_n_kw 50 blocks
../py/objboundmeth.c:69 bound_meth_call 1 blocks
../py/runtime.c:577 mp_call_function_n_kw 1 blocks
../py/objfun.c:86 fun_builtin_2_call 1 blocks
../py/objproperty.c:66 property_setter 1 blocks
../py/objtype.c:816 type_call 49 blocks
../py/objtype.c:248 mp_obj_instance_make_new 7 blocks
../py/objtype.c:52 mp_obj_new_instance 7 blocks
../py/objtype.c:312 mp_obj_instance_make_new 42 blocks
../py/runtime.c:594 mp_call_method_n_kw 42 blocks
../py/runtime.c:577 mp_call_function_n_kw 42 blocks
../py/objfun.c:275 fun_bc_call 42 blocks
../py/vm.c:381 mp_execute_bytecode 14 blocks
../py/obj.c:442 mp_obj_subscr 14 blocks
../py/objarray.c:461 array_subscr 14 blocks
../py/vm.c:415 mp_execute_bytecode 14 blocks
../py/runtime.c:1083 mp_store_attr 14 blocks
../py/objtype.c:645 mp_obj_instance_attr 14 blocks
../py/objtype.c:636 mp_obj_instance_store_attr 14 blocks
../py/map.c:283 mp_map_lookup 14 blocks
../py/map.c:130 mp_map_rehash 14 blocks
../py/vm.c:903 mp_execute_bytecode 14 blocks
../py/runtime.c:577 mp_call_function_n_kw 14 blocks
../py/objtype.c:816 type_call 14 blocks
../py/objarray.c:192 bytearray_make_new 14 blocks
../py/objarray.c:100 array_new 7 blocks
../py/objarray.c:111 array_new 7 blocks
../py/modbuiltins.c:80 mp_builtin___build_class__ 1 blocks
../py/objtuple.c:242 mp_obj_new_tuple 1 blocks
../py/modbuiltins.c:82 mp_builtin___build_class__ 20 blocks
../py/runtime.c:577 mp_call_function_n_kw 20 blocks
../py/objtype.c:816 type_call 20 blocks
../py/objtype.c:794 type_make_new 20 blocks
../py/objtype.c:904 mp_obj_new_type 20 blocks
../py/vm.c:974 mp_execute_bytecode 6 blocks
../py/runtime.c:594 mp_call_method_n_kw 6 blocks
../py/runtime.c:577 mp_call_function_n_kw 6 blocks
../py/objfun.c:86 fun_builtin_2_call 6 blocks
../py/objnamedtuple.c:169 new_namedtuple_type 6 blocks
../py/objnamedtuple.c:140 mp_obj_new_namedtuple_type 6 blocks
../py/vm.c:400 mp_execute_bytecode 2 blocks
../py/runtime.c:168 mp_store_name 2 blocks
../py/objdict.c:612 mp_obj_dict_store 2 blocks
../py/map.c:283 mp_map_lookup 2 blocks
../py/map.c:130 mp_map_rehash 2 blocks
main.c:321 main 2 blocks
../lib/utils/pyexec.c:374 pyexec_friendly_repl 2 blocks
../py/vstr.c:46 vstr_init 2 blocks
296 total blocks
```
To load the json file in the browser install http-server with npm
(`npm install -g http-server`) and run it from the `micropython` directory with
`http-server`.
Navigate to `https://127.0.0.1/tools/gc_activity.html` to see the data. (You
will likely need to edit the html to point to the right place for your file.)

94
tools/gc_activity.py Normal file
View File

@ -0,0 +1,94 @@
import sys
import json
# Map start block to current allocation info.
current_heap = {}
allocation_history = []
root = {}
def change_root(trace, size):
level = root
for frame in reversed(trace):
file_location = frame[1]
if file_location not in level:
level[file_location] = {"blocks": 0,
"file": file_location,
"function": frame[2],
"subcalls": {}}
level[file_location]["blocks"] += size
level = level[file_location]["subcalls"]
total_actions = 0
with open(sys.argv[1], "r") as f:
for line in f:
if not line.strip():
break
for line in f:
action = None
if line.startswith("Breakpoint 2"):
break
next(f) # throw away breakpoint code line
next(f) # first frame
block = 0
size = 0
trace = []
for line in f:
#print(line.strip())
if line[0] == "#":
frame = line.strip().split()
if frame[1].startswith("0x"):
trace.append((frame[1], frame[-1], frame[3]))
else:
trace.append(("0x0", frame[-1], frame[1]))
elif line[0] == "$":
block = int(line.strip().split()[-1][2:], 16)
size = int(next(f).strip().split()[-1][2:], 16)
if not line.strip():
break
action = "unknown"
if block not in current_heap:
current_heap[block] = {"start_block": block, "size": size, "start_trace": trace, "start_time": total_actions}
action = "alloc"
change_root(trace, size)
else:
alloc = current_heap[block]
alloc["end_trace"] = trace
alloc["end_time"] = total_actions
change_root(alloc["start_trace"], -1 * alloc["size"])
if size > 0:
action = "realloc"
current_heap[block] = {"start_block": block, "size": size, "start_trace": trace, "start_time": total_actions}
change_root(trace, size)
else:
action = "free"
if trace[0][2] == "gc_sweep":
action = "sweep"
del current_heap[block]
alloc["end_cause"] = action
allocation_history.append(alloc)
print(total_actions, action, block, size)
total_actions += 1
print()
for alloc in current_heap.values():
alloc["end_trace"] = ""
alloc["end_time"] = total_actions
allocation_history.append(alloc)
def print_frame(frame, indent=0):
for key in sorted(frame):
if not frame[key]["blocks"] or key.startswith("../py/malloc.c") or key.startswith("../py/gc.c"):
continue
print(" " * (indent - 1), key, frame[key]["function"], frame[key]["blocks"], "blocks")
print_frame(frame[key]["subcalls"], indent + 2)
print_frame(root)
total_blocks = 0
for key in sorted(root):
total_blocks += root[key]["blocks"]
print(total_blocks, "total blocks")
with open("allocation_history.json", "w") as f:
json.dump(allocation_history, f)

28
tools/output_gc_until_repl.txt Normal file
View File

@ -0,0 +1,28 @@
tar ext :2331
monitor reset
set width 0
set height 0
set verbose off
set logging file mylog.txt
set logging overwrite on
set logging redirect on
set logging on
set remote hardware-breakpoint-limit 4
# gc log
break gc.c:110
commands
backtrace
p/x start_block
p/x length
continue
end
break mp_hal_stdin_rx_chr
continue
delete
disconnect
quit