Lua memory (de)allocation tracer: (#5191)

* Lua memory (de)allocation tracer:

Usage:
 * turn on: `cmake -DLUA=YES -DLUA_ALLOCATOR_TRACER=YES -DDEBUG=YES -DNANO=NO`
 * get debug output and make plot data: `./simu 2>&1 | grep "^LT" | ../radio/util/lua_trace2plot.py > data.plot`
 * plot: `gnuplot  -e 'set xtics rotate;  plot "data.plot" using 2:xtic(1) ; pause mouse close'`

* Changes based on Bertrand comments

radio/src/CMakeLists.txt

@@ -195,6 +195,9 @@ if(NOT LUA STREQUAL NO)
   if(LUA_COMPILER)
     add_definitions(-DLUA_COMPILER)
   endif()
+  if(LUA_ALLOCATOR_TRACER AND DEBUG)
+    add_definitions(-DLUA_ALLOCATOR_TRACER)
+  endif()
   if(NOT "${LUA_SCRIPT_LOAD_MODE}" STREQUAL "")
     add_definitions(-DLUA_SCRIPT_LOAD_MODE="${LUA_SCRIPT_LOAD_MODE}")
   endif()

radio/src/lua/interface.cpp

@@ -51,6 +51,39 @@ struct our_longjmp * global_lj = 0;
 uint32_t luaExtraMemoryUsage = 0;
 #endif
 
+#if defined(LUA_ALLOCATOR_TRACER)
+
+LuaMemTracer lsScriptsTrace;
+
+#if defined(PCBHORUS)
+  extern LuaMemTracer lsWidgetsTrace;
+  #define GET_TRACER(L)    (L == lsScripts) ? &lsScriptsTrace : &lsWidgetsTrace
+#else
+  #define GET_TRACER(L)    &lsScriptsTrace
+#endif
+
+void *tracer_alloc(void * ud, void * ptr, size_t osize, size_t nsize)
+{
+  LuaMemTracer * tracer = (LuaMemTracer *)ud;
+  if (ptr) {
+    if (osize < nsize) {
+      // TRACE("Lua alloc %u", nsize - osize);
+      tracer->alloc += nsize - osize;
+    }
+    else {
+      // TRACE("Lua free %u", osize - nsize);
+      tracer->free += osize - nsize;
+    }
+  }
+  else {
+    // TRACE("Lua alloc %u (type %s)", nsize, osize < LUA_TOTALTAGS ? lua_typename(0, osize) : "unk");
+    tracer->alloc += nsize;
+  }
+  return l_alloc(ud, ptr, osize, nsize);
+}
+
+#endif // #if defined(LUA_ALLOCATOR_TRACER)
+
 /* custom panic handler */
 int custom_lua_atpanic(lua_State * L)
 {
@@ -64,6 +97,7 @@ int custom_lua_atpanic(lua_State * L)
 
 void luaHook(lua_State * L, lua_Debug *ar)
 {
+  if (ar->event == LUA_HOOKCOUNT) {
     instructionsPercent++;
 #if defined(DEBUG)
   // Disable Lua script instructions limit in DEBUG mode,
@@ -86,12 +120,30 @@ void luaHook(lua_State * L, lua_Debug *ar)
       luaL_error(L, "CPU limit");
     }
 #endif
+  }
+#if defined(LUA_ALLOCATOR_TRACER)
+  else if (ar->event == LUA_HOOKLINE) {
+    lua_getinfo(L, "nSl", ar);
+    LuaMemTracer * tracer = GET_TRACER(L);
+    if (tracer->alloc || tracer->free) {
+      TRACE("LT: [+%u,-%u] %s:%d", tracer->alloc, tracer->free, tracer->script, tracer->lineno);
+    }
+    tracer->script = ar->source;
+    tracer->lineno = ar->currentline;
+    tracer->alloc = 0;
+    tracer->free = 0;
+  }
+#endif // #if defined(LUA_ALLOCATOR_TRACER)
 }
 
 void luaSetInstructionsLimit(lua_State * L, int count)
 {
   instructionsPercent = 0;
+#if defined(LUA_ALLOCATOR_TRACER)
+  lua_sethook(L, luaHook, LUA_MASKCOUNT|LUA_MASKLINE, count);
+#else
   lua_sethook(L, luaHook, LUA_MASKCOUNT, count);
+#endif
 }
 
 int luaGetInputs(lua_State * L, ScriptInputsOutputs & sid)
@@ -189,6 +241,14 @@ void luaClose(lua_State ** L)
     PROTECT_LUA() {
       TRACE("luaClose %p", *L);
       lua_close(*L);  // this should not panic, but we make sure anyway
+#if defined(LUA_ALLOCATOR_TRACER)
+      LuaMemTracer * tracer = GET_TRACER(*L);
+      if (tracer->alloc || tracer->free) {
+        TRACE("LT: [+%u,-%u] luaClose(%s)", tracer->alloc, tracer->free, (*L == lsScripts) ? "scipts" : "widgets");
+      }
+      tracer->alloc = 0;
+      tracer->free = 0;
+#endif // #if defined(LUA_ALLOCATOR_TRACER)
     }
     else {
       // we can only disable Lua for the rest of the session
@@ -1017,6 +1077,10 @@ void luaInit()
   if (luaState != INTERPRETER_PANIC) {
 #if defined(USE_BIN_ALLOCATOR)
     lsScripts = lua_newstate(bin_l_alloc, NULL);   //we use our own allocator!
+#elif defined(LUA_ALLOCATOR_TRACER)
+    memset(&lsScriptsTrace, 0 , sizeof(lsScriptsTrace));
+    lsScriptsTrace.script = "lua_newstate(scripts)";
+    lsScripts = lua_newstate(tracer_alloc, &lsScriptsTrace);   //we use tracer allocator
 #else
     lsScripts = lua_newstate(l_alloc, NULL);   //we use Lua default allocator
 #endif
@@ -1024,6 +1088,10 @@ void luaInit()
       // install our panic handler
       lua_atpanic(lsScripts, &custom_lua_atpanic);
 
+#if defined(LUA_ALLOCATOR_TRACER)
+      lua_sethook(lsScripts, luaHook, LUA_MASKLINE, 0);
+#endif
+
       // protect libs and constants registration
       PROTECT_LUA() {
         luaRegisterLibraries(lsScripts);

radio/src/lua/lua_api.h

@@ -168,10 +168,24 @@ void luaRegisterLibraries(lua_State * L);
 void registerBitmapClass(lua_State * L);
 void luaSetInstructionsLimit(lua_State* L, int count);
 int luaLoadScriptFileToState(lua_State * L, const char * filename, const char * mode);
+
+struct LuaMemTracer {
+  const char * script;
+  int lineno;
+  uint32_t alloc;
+  uint32_t free;
+};
+
+void * tracer_alloc(void * ud, void * ptr, size_t osize, size_t nsize);
+void luaHook(lua_State * L, lua_Debug *ar);
+
+
 #else  // defined(LUA)
+
 #define luaInit()
 #define LUA_INIT_THEMES_AND_WIDGETS()
 #define LUA_LOAD_MODEL_SCRIPTS()
+
 #endif // defined(LUA)
 
 #endif // _LUA_API_H_

radio/src/lua/widgets.cpp

@@ -514,12 +514,20 @@ void luaLoadFiles(const char * directory, void (*callback)())
   f_closedir(&dir);
 }
 
+#if defined(LUA_ALLOCATOR_TRACER)
+LuaMemTracer lsWidgetsTrace;
+#endif
+
 void luaInitThemesAndWidgets()
 {
   TRACE("luaInitThemesAndWidgets");
 
 #if defined(USE_BIN_ALLOCATOR)
   lsWidgets = lua_newstate(bin_l_alloc, NULL);   //we use our own allocator!
+#elif defined(LUA_ALLOCATOR_TRACER)
+  memset(&lsWidgetsTrace, 0 , sizeof(lsWidgetsTrace));
+  lsWidgetsTrace.script = "lua_newstate(widgets)";
+  lsWidgets = lua_newstate(tracer_alloc, &lsWidgetsTrace);   //we use tracer allocator
 #else
   lsWidgets = lua_newstate(l_alloc, NULL);   //we use Lua default allocator
 #endif
@@ -527,6 +535,10 @@ void luaInitThemesAndWidgets()
     // install our panic handler
     lua_atpanic(lsWidgets, &custom_lua_atpanic);
 
+#if defined(LUA_ALLOCATOR_TRACER)
+    lua_sethook(lsWidgets, luaHook, LUA_MASKLINE, 0);
+#endif
+
     // protect libs and constants registration
     PROTECT_LUA() {
       luaRegisterLibraries(lsWidgets);

radio/src/targets/common/arm/stm32/CMakeLists.txt

@@ -2,6 +2,7 @@ set(LUA "NO" CACHE STRING "Lua scripts (YES/NO/NO_MODEL_SCRIPTS)")
 set_property(CACHE LUA PROPERTY STRINGS YES NO NO_MODEL_SCRIPTS)
 set(LUA_SCRIPT_LOAD_MODE "" CACHE STRING "Script loading mode and compilation flags [btTxcd] (see loadScript() API docs). Blank for default ('bt' on radio, 'T' on SIMU/DEBUG builds)")
 option(LUA_COMPILER "Pre-compile and save Lua scripts" OFF)
+option(LUA_ALLOCATOR_TRACER "Trace Lua memory (de)allocations to debug port (also needs DEBUG=YES NANO=NO)" OFF)
 
 set(ARCH ARM)
 set(STM32USB_DIR ${THIRDPARTY_DIR}/STM32_USB-Host-Device_Lib_V2.2.0/Libraries)

radio/util/lua_trace2plot.py

@@ -0,0 +1,55 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+
+"""
+    This script parses debug log events related to Lua memory (de)allocations ( lines
+    starting wiht "LT: ") and produces a data for gnuplot program
+
+    Usage:
+
+        ./simu 2>&1 | grep "^LT" | ../radio/util/lua_trace2plot.py > data.plot
+        gnuplot  -e 'set xtics rotate;  plot "data.plot" using 2:xtic(1) ; pause mouse close'
+"""
+
+from __future__ import print_function
+
+import sys
+
+
+if len(sys.argv) > 1:
+    inputFile = sys.argv[1]
+    inp = open(inputFile, "r")
+else:
+    inp = sys.stdin
+
+
+x = 0
+memUsed = 0
+while True:
+    skip = True
+    line = inp.readline()
+    if len(line) == 0:
+        break
+    line = line.strip('\r\n')
+    if len(line) == 0:
+        skip = True
+    if line.startswith("LT:"):
+        skip = False
+
+    if not skip:
+        parts = line.split()
+        if len(parts) >= 3:
+            data = parts[1].strip("[").strip("]").split(",")
+            alloc = int(data[0])
+            free = int(data[1])
+            line = parts[2]
+            if alloc > 0:
+                memUsed += alloc
+                print("'%s'\t%d" % (line, memUsed))
+                x += 1
+            if free < 0:
+                memUsed += free
+                print("'%s'\t%d" % (line, memUsed))
+                x += 1
+
+inp.close()