commit b335c8c7de73dfe3caeb88f91f8b3bc895c19497 from: Matthias L. Jugel date: Mon Jan 14 21:31:00 2019 UTC update memtrace.py to work without a log file commit - 63f886b17113fc454e9bee0d414ad13f433b1989 commit + b335c8c7de73dfe3caeb88f91f8b3bc895c19497 blob - 95bd134181e8918044f066de53b7d3ddf9670b13 blob + c7d69705cf53531a05d97d641404660df1c3016e --- README.md +++ README.md @@ -1,54 +1,34 @@ # mbed-memtrace-logger + Analyzes and logs the memtrace output from mbed-os in a readable form. +This code is left over for the use with micro:bit and Calliope mini. -The memory trace outputs pretty unreadable information: +If you look for the original memtrace, check out the mbed-cli. -``` -#m:0x20003080;0x182f-50 -#f:0x0;0x183f-0x20003080 -#m:0x20003080;0x182f-50 -#f:0x0;0x183f-0x20003080 -#m:0x20003080;0x182f-50 -#f:0x0;0x183f-0x20003080 -``` +> You need to enable heap debug output! -The script takes those lines and converts them into a little more readable -information and also calculates the currently allocated heap: +Run with: `python3 memtrace.py /dev/cu.XXXXX 115200` +The script auto-resets the counts and output looks like: ``` -$ python bin/memtrace.py test.log test -RESETTING tracer on 'test' - -== (001) 50 [ 32] +50 (#m:0x20003080;0x182f-50) -== (000) 0 [ 0] -50 (#f:0x0;0x183f-0x20003080) -== (001) 50 [ 32] +50 (#m:0x20003080;0x182f-50) -== (000) 0 [ 0] -50 (#f:0x0;0x183f-0x20003080) -== (001) 50 [ 32] +50 (#m:0x20003080;0x182f-50) -== (000) 0 [ 0] -50 (#f:0x0;0x183f-0x20003080) +HEAP 0: +heap_start : 0x20002950 +heap_end : 0x20003600 +heap_size : 3248 +[F:3248] +mb_total_free : 3248 +mb_total_used : 0 +== (001) 56 [20002954] +56 (malloc: ALLOCATED: 56 [0x20002954]) +== (002) 76 [20002990] +20 (malloc: ALLOCATED: 20 [0x20002990]) +== (003) 124 [200029a8] +48 (malloc: ALLOCATED: 48 [0x200029a8]) +... +== (032) 1254 [20002e50] -18 (free: 0x20002e50) +== (031) 1229 [20002ea8] -25 (free: 0x20002ea8) +== (030) 1209 [20002e90] -20 (free: 0x20002e90) +... +Calliope Accelerometer Test v1.0 ``` -Even in color :-): - -![logoutput.png](logoutput.png) - -# Using a log file -- enable memory tracing in your mbed program -- log uart output into a file -- run script to analyze memory state - -# Using a stream -- enable memory tracing in your mbed program -- log uart into a log file continuously: `miniterm.py /dev/cu.usbmodem1234 9600 | tee memtrace.log` -- run script to tail file `python memtrace.py memtrace.log KEYWORD` - -> the KEYWORD allows you to define a RESET state, where the analyzer resets all calculations. - -# Required libraries: - -- `Pygtail`, install: `pip install pygtail` - -Enjoy! - ## License ``` blob - 232f8f4134a6d2b32c404995632a116bd405e28c (mode 644) blob + /dev/null --- memtrace-calliope.py +++ /dev/null @@ -1,101 +0,0 @@ -""" -A simple mbed memtrace log extractor, calculating allocated memory. - -Author: Matthias L. Jugel (@thinkberg) - -Prerequisites: - pip install pygtail - -Usage: - python memtrace.py log-file mem-reset-keyword - - The script will tail the log file and reset the memory counter when - the mem-reset-keyword occurs. - - a) enable memory tracing in your embedded program (config.json): - ``` - { - "microbit-dal": { - "debug": 1, - "heap": { - "debug": 1 - } - } - } - ``` - - b) Log into a file: - `$ miniterm.py /dev/cu.usbmodem142111 9600 | tee memtrace.log` - - c) Analyze log file (tails the log file) - python -u bin/memtrace.py memtrace.log SHCSR - - If the analyzer behaves strangely, delete the "log-file.offset" file. -""" - -import re -import sys - -import time - -from pygtail import Pygtail - -mem = {} -allocated = 0 - -reset = None -if len(sys.argv) > 1: - reset = sys.argv[2] - print "RESETTING tracer on '%s'" % reset - -r_malloc = re.compile("^(microbit_)malloc:\\s+(NATIVE\\s+)?(ALLOCATED:)\\s+(\\d+)\\s+\\[(0x[0-9a-f]+)\\]") -r_free = re.compile("^(microbit_)free:\\s+(0x[0-9a-f]+)") - -partial = "" -while True: - for line in Pygtail(sys.argv[1]): - # we sometimes get incomplete lines, wait for a full line - if not (line[-1] == '\n' or line[-1] == '\r'): - partial = line - continue - else: - line = partial + line - partial = "" - - # strip newline and carriage return - line = line.rstrip('\n').rstrip('\r') - - # if we detect the reset keyword, rest the map and memory counter - if reset in line: - mem = {} - allocated = 0 - print "\n\n\033[91m>> RESET >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>\033[0m" - - # match malloc, realloc and free - m = r_malloc.search(line) - if m: - mem[m.group(5)] = int(m.group(4)) - allocated += int(m.group(4)) - print "\033[1m== (%03d) \033[34m%8d\033[0m [%8x] \033[31m+%-6d\033[0m (%s)" % \ - (len(mem), allocated, allocated, int(m.group(4)), - m.group(0).replace(m.group(1), "").replace(m.group(3), "")) - continue - - m = r_free.search(line) - if m: - # print "f", m.group(3) - freed = 0 - if mem.has_key(m.group(2)): - freed = mem[m.group(2)] - allocated -= freed - del mem[m.group(2)] - else: - print "\033[33m!! WARN: free(%s)\033[0m" % m.group(1) - print "\033[1m== (%03d) \033[34m%8d\033[0m [%8x] \033[92m-%-6d\033[0m (%s)" % \ - (len(mem), allocated, allocated, freed, m.group(0).replace(m.group(1), "")) - continue - - # print all other lines as is, so we can still use the log functionality - print line - sys.stdout.flush() - time.sleep(1) blob - 26db34e700d231ba149f3dea02860620fdd357db blob + 923e2284830d1e0a67f22a19c83b24935c8803ef --- memtrace.py +++ memtrace.py @@ -1,132 +1,53 @@ -""" -A simple mbed memtrace log extractor, calculating allocated memory. - -Author: Matthias L. Jugel (@thinkberg) - -Prerequisites: - pip install pygtail - -Usage: - python memtrace.py log-file mem-reset-keyword - - The script will tail the log file and reset the memory counter when - the mem-reset-keyword occurs. - - a) enable memory tracing in your embedded program: - ``` - #ifdef MBED_MEM_TRACING_ENABLED - mbed_mem_trace_set_callback(mbed_mem_trace_default_callback); - #endif - ``` - - b) Log into a file: - `$ miniterm.py /dev/cu.usbmodem142111 9600 | tee memtrace.log` - - c) Analyze log file (tails the log file) - python -u bin/memtrace.py memtrace.log SHCSR - - If the analyzer behaves strangely, delete the "log-file.offset" file. -""" - -import re import sys -import time +from memtrace_calliope_trns import CalliopeDebugTransform -from pygtail import Pygtail -mem = {} -allocated = 0 +class TraceTerminal(object): + serial = None # Serial() object + port = None + baudrate = None + echo = None -reset = None -if len(sys.argv) > 1: - reset = sys.argv[2] - print "RESETTING tracer on '%s'" % reset + def __init__(self, port, baudrate=9600, echo=True, timeout=10): + self.port = port + self.baudrate = int(baudrate) + self.timeout = int(timeout) + self.echo = False if str(echo).lower() == 'off' else True -r_malloc = re.compile("([^#]*)#m:(0x[0-9a-f]+);(0x[0-9a-f]+)-(\\d+)") -r_calloc = re.compile("([^#]*)#c:(0x[0-9a-f]+);(0x[0-9a-f]+)-(\\d+);(\\d+)") -r_realloc = re.compile("([^#]*)#r:(0x[0-9a-f]+);(0x[0-9a-f]+)-(0x[0-9a-f]+);(\\d+)") -r_free = re.compile("([^#]*)#f:(0x[0-9a-f]+);(0x[0-9a-f]+)-(0x[0-9a-f]+)") + try: + from serial import Serial, SerialException + self.serial = Serial(self.port, baudrate=self.baudrate, timeout=self.timeout) + self.serial.flush() + self.serial.reset_input_buffer() + except (IOError, ImportError, OSError, Exception): + self.serial = None + return -partial = "" -while True: - for line in Pygtail(sys.argv[1]): - # we sometimes get incomplete lines, wait for a full line - if not (line[-1] == '\n' or line[-1] == '\r'): - partial = line - continue - else: - line = partial + line - partial = "" + def terminal(self): + try: + import serial.tools.miniterm as miniterm + except (IOError, ImportError, OSError) as e: + print(repr(e)) + return False - # strip newline and carriage return - line = line.rstrip('\n').rstrip('\r') + term = miniterm.Miniterm(self.serial, echo=self.echo) + term.exit_character = '\x03' + term.menu_character = '\x14' + term.set_rx_encoding('UTF-8') + term.set_tx_encoding('UTF-8') - # if we detect the reset keyword, rest the map and memory counter - if reset in line: - mem = {} - allocated = 0 - print "\n\n\033[91m>> RESET >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>\033[0m" + term.rx_transformations += [CalliopeDebugTransform()] - # match malloc, realloc and free - m = r_malloc.search(line) - if m: - if len(m.group(1)): print m.group(1) - # print "m", m.group(2), ":", m.group(4) - if m.group(2) == "0x0": - print "\033[1m!! (%03d) \033[31mmalloc failed\033[0m (%s)" % (len(mem), line) - else: - mem[m.group(2)] = int(m.group(4)) - allocated += int(m.group(4)) - print "\033[1m== (%03d) \033[34m%8d\033[0m [%8x] \033[31m+%-6d\033[0m (%s)" % \ - (len(mem), allocated, allocated, int(m.group(4)), line.replace(m.group(1), "")) - continue + term.start() - m = r_calloc.search(line) - if m: - if len(m.group(1)): print m.group(1) - # print "c", m.group(2), ":", m.group(4), "*", m.group(5) - if m.group(2) == "0x0": - print "\033[1m!! (%03d) \033[31mcalloc failed\033[0m (%s)" % (len(mem), line) - else: - total = int(m.group(4)) * int(m.group(5)) - mem[m.group(2)] = total - allocated += total - print "\033[1m== (%03d) \033[34m%8d\033[0m [%8x] \033[31m+%-6d\033[0m (%s)" % \ - (len(mem), allocated, allocated, total, line.replace(m.group(1), "")) - continue + try: + term.join(True) + except KeyboardInterrupt: + pass + term.join() + term.close() - m = r_realloc.search(line) - if m: - if len(m.group(1)): print m.group(1) - # print "r", m.group(2), ":", m.group(5) - diff = 0 - if mem.has_key(m.group(2)): - diff = int(m.group(5)) - mem[m.group(2)] - mem[m.group(2)] = int(m.group(5)) - else: - print "\033[33m!! WARN: realloc() without previous allocation\033[0m (%s)" % line - allocated += diff - print "\033[1m== (%03d) \033[34m%8d\033[0m [%8x] \033[35m+%-6d\033[0m (%s)" % \ - (len(mem), allocated, allocated, diff, line.replace(m.group(1), "")) - continue +term = TraceTerminal(sys.argv[1], int(sys.argv[2])).terminal() - m = r_free.search(line) - if m: - if len(m.group(1)): print m.group(1) - # print "f", m.group(3) - freed = 0 - if mem.has_key(m.group(4)): - freed = mem[m.group(4)] - allocated -= freed - del mem[m.group(4)] - else: - print "\033[33m!! WARN: free(%s)\033[0m" % m.group(4) - print "\033[1m== (%03d) \033[34m%8d\033[0m [%8x] \033[92m-%-6d\033[0m (%s)" % \ - (len(mem), allocated, allocated, freed, line.replace(m.group(1), "")) - continue - # print all other lines as is, so we can still use the log functionality - print line - sys.stdout.flush() - time.sleep(1) blob - /dev/null blob + 4f35c1a0516289063bdbcaedce3d6a2f12a91bbb (mode 644) --- /dev/null +++ memtrace_calliope_trns.py @@ -0,0 +1,93 @@ +# mbed debug trace transformer, handling memory trace information +# Author: Matthias L. Jugel (@thinkberg) +# +# Copyright (c) 2018 ubirch GmbH, All Rights Reserved +# SPDX-License-Identifier: Apache-2.0 +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# +# You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an +# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, +# either express or implied. + +import re +import sys + +from serial.tools.miniterm import Transform + +def debug(s): + sys.stderr.write("D "+repr(s)+"\r\n") + +class CalliopeDebugTransform(Transform): + mem = {} + allocated = 0 + reset = None + buffer = "" + + def __init__(self): + self.r_malloc = re.compile("(?:microbit_)?malloc:\s+(?:NATIVE\s+)?(?:ALLOCATED:)\s+(\d+)\s+\[(0x[0-9a-f]+)\]") + self.r_free = re.compile("^(?:microbit_)?free:\\s+(0x[0-9a-f]+)") + self.r_heap_size = re.compile("^mb_total_free : (\d+)") + + def rx(self, rx_input): + # collect lines + out = "" + for c in rx_input: + if c == '\r' or c == '\n': + if len(self.buffer): + out += self.trace_line(self.buffer) + else: + out += "\n" + self.buffer = "" + continue + else: + self.buffer += c + continue + return out + + def trace_line(self, line): + # strip newline and carriage return + line = line.rstrip('\n').rstrip('\r') + + m = self.r_heap_size.search(line) + if m: + self.max = int(m.group(1)) + self.mem = {} + self.allocated = 0 + line += "\r\n\r\n\033[91m>> RESET HEAP COUNTERS >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>\033[0m\r\n" + line += "\033[4m (NUM) TOTAL [ ADDRESS] CHANGE (COMMENT)\033[0m\r\n" + return line + + # match malloc, realloc and free + m = self.r_malloc.search(line) + if m: + out = "" + if m.group(2) == "0": + out += "\033[1m!! (%03d) \033[31mmalloc failed\033[0m (%s)\r\n" % (len(self.mem), line) + else: + self.mem[m.group(2)] = int(m.group(1)) + self.allocated += int(m.group(1)) + out += "\033[1m== (%03d) \033[34m%8d\033[0m [%8x] \033[31m+%-6d\033[0m (%s)\r\n" % \ + (len(self.mem), self.allocated, int(m.group(2), 16), int(m.group(1)), line) + return out + + m = self.r_free.search(line) + if m: + out = "" + freed = 0 + if m.group(1) in self.mem: + freed = self.mem[m.group(1)] + self.allocated -= freed + del self.mem[m.group(1)] + else: + out += "\033[33m!! (%03d) WARN: free(0x%s)\033[0m\r\n" % (len(self.mem), m.group(4)) + out += "\033[1m== (%03d) \033[34m%8d\033[0m [%8x] \033[92m-%-6d\033[0m (%s)\r\n" % \ + (len(self.mem), self.allocated, int(m.group(1), 16), freed, line) + return out + + # print all other lines as is, so we can still use the log functionality + return line + "\r\n"