diff --git a/libraries/AP_Logger/LogStructure.h b/libraries/AP_Logger/LogStructure.h index 261f6e17e56e0..23c8b1fb60686 100644 --- a/libraries/AP_Logger/LogStructure.h +++ b/libraries/AP_Logger/LogStructure.h @@ -635,7 +635,8 @@ struct PACKED log_Scripting { char name[16]; uint32_t run_time; int32_t total_mem; - int32_t run_mem; + int32_t script_mem; + int32_t run_allocation; }; struct PACKED log_MotBatt { @@ -1158,7 +1159,8 @@ struct PACKED log_VER { // @Field: Name: script name // @Field: Runtime: run time // @Field: Total_mem: total memory usage of all scripts -// @Field: Run_mem: run memory usage +// @Field: mem: memory usage of this script +// @Field: alloc: memory allocated during this run // @LoggerMessage: VER // @Description: Ardupilot version @@ -1303,7 +1305,7 @@ LOG_STRUCTURE_FROM_VISUALODOM \ "FILE", "NIBZ", "FileName,Offset,Length,Data", "----", "----" }, \ LOG_STRUCTURE_FROM_AIS \ { LOG_SCRIPTING_MSG, sizeof(log_Scripting), \ - "SCR", "QNIii", "TimeUS,Name,Runtime,Total_mem,Run_mem", "s#sbb", "F-F--", true }, \ + "SCR", "QNIiii", "TimeUS,Name,Runtime,Total_mem,mem,alloc", "s#sbbb", "F-F---", true }, \ { LOG_VER_MSG, sizeof(log_VER), \ "VER", "QBHBBBBIZHBB", "TimeUS,BT,BST,Maj,Min,Pat,FWT,GH,FWS,APJ,BU,FV", "s-----------", "F-----------", false }, \ { LOG_MOTBATT_MSG, sizeof(log_MotBatt), \ diff --git a/libraries/AP_Scripting/lua_scripts.cpp b/libraries/AP_Scripting/lua_scripts.cpp index 98960a11ceba6..6e1dd02c1860f 100644 --- a/libraries/AP_Scripting/lua_scripts.cpp +++ b/libraries/AP_Scripting/lua_scripts.cpp @@ -35,6 +35,8 @@ char *lua_scripts::error_msg_buf; HAL_Semaphore lua_scripts::error_msg_buf_sem; uint8_t lua_scripts::print_error_count; uint32_t lua_scripts::last_print_ms; +size_t lua_scripts::allocated; +size_t lua_scripts::deallocated; uint32_t lua_scripts::loaded_checksum; uint32_t lua_scripts::running_checksum; @@ -128,23 +130,24 @@ int lua_scripts::atpanic(lua_State *L) { } // helper for print and log of runtime stats -void lua_scripts::update_stats(const char *name, uint32_t run_time, int total_mem, int run_mem) +void lua_scripts::update_stats(const char *name, uint32_t run_time, int total_mem, int script_mem, int run_allocation) { if ((_debug_options.get() & uint8_t(DebugLevel::RUNTIME_MSG)) != 0) { GCS_SEND_TEXT(MAV_SEVERITY_DEBUG, "Lua: Time: %u Mem: %d + %d", (unsigned int)run_time, - (int)total_mem, - (int)run_mem); + (int)script_mem, + (int)run_allocation); } #if HAL_LOGGING_ENABLED if ((_debug_options.get() & uint8_t(DebugLevel::LOG_RUNTIME)) != 0) { struct log_Scripting pkt { LOG_PACKET_HEADER_INIT(LOG_SCRIPTING_MSG), - time_us : AP_HAL::micros64(), - name : {}, - run_time : run_time, - total_mem : total_mem, - run_mem : run_mem + time_us : AP_HAL::micros64(), + name : {}, + run_time : run_time, + total_mem : total_mem, + script_mem : script_mem, + run_allocation : run_allocation }; const char * name_short = strrchr(name, '/'); if ((strlen(name) > sizeof(pkt.name)) && (name_short != nullptr)) { @@ -158,6 +161,13 @@ void lua_scripts::update_stats(const char *name, uint32_t run_time, int total_me } lua_scripts::script_info *lua_scripts::load_script(lua_State *L, char *filename) { +#if defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 + const int startMem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); + if ((allocated != 0) || (deallocated != 0)) { + AP_HAL::panic("Lua: unexpected memory use in load"); + } +#endif + if (int error = luaL_loadfile(L, filename)) { switch (error) { case LUA_ERRSYNTAX: @@ -179,7 +189,6 @@ lua_scripts::script_info *lua_scripts::load_script(lua_State *L, char *filename) } } - const int loadMem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); const uint32_t loadStart = AP_HAL::micros(); script_info *new_script = (script_info *)_heap.allocate(sizeof(script_info)); @@ -194,11 +203,6 @@ lua_scripts::script_info *lua_scripts::load_script(lua_State *L, char *filename) create_sandbox(L); lua_setupvalue(L, -2, 1); - const uint32_t loadEnd = AP_HAL::micros(); - const int endMem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); - - update_stats(filename, loadEnd-loadStart, endMem, loadMem); - new_script->name = filename; new_script->lua_ref = luaL_ref(L, LUA_REGISTRYINDEX); // cache the reference new_script->next_run_ms = AP_HAL::millis64() - 1; // force the script to be stale @@ -216,6 +220,20 @@ lua_scripts::script_info *lua_scripts::load_script(lua_State *L, char *filename) } } + // Update runtime stats + const uint32_t loadEnd = AP_HAL::micros(); + const int endMem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); + + const int loadMem = allocated - deallocated; + new_script->memory = loadMem; + update_stats(filename, loadEnd-loadStart, endMem, loadMem, allocated); + +#if defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 + if ((endMem - startMem) != loadMem) { + AP_HAL::panic("Lua: load memory does not match"); + } +#endif + return new_script; } @@ -284,6 +302,11 @@ void lua_scripts::load_all_scripts_in_dir(lua_State *L, const char *dirname) { // we have something that looks like a lua file, attempt to load it script_info * script = load_script(L, filename); + + // Clear memory totals to measure the next load + allocated = 0; + deallocated = 0; + if (script == nullptr) { _heap.deallocate(filename); continue; @@ -414,6 +437,7 @@ void lua_scripts::remove_script(lua_State *L, script_info *script) { } _heap.deallocate(script->name); _heap.deallocate(script); + script = nullptr; } void lua_scripts::reschedule_script(script_info *script) { @@ -455,7 +479,20 @@ MultiHeap lua_scripts::_heap; void *lua_scripts::alloc(void *ud, void *ptr, size_t osize, size_t nsize) { (void)ud; /* not used */ - return _heap.change_size(ptr, osize, nsize); + const bool nullprt_in = ptr == nullptr; + void * ret = _heap.change_size(ptr, osize, nsize); + + // Track memory usage + if ((ret != nullptr) || (nsize == 0)) { + allocated += nsize; + if (!nullprt_in) { + // If old object is nullptr the old size should always be zero + // This is not always the case.... + deallocated += osize; + } + } + + return ret; } void lua_scripts::repl_cleanup (void) { @@ -469,10 +506,15 @@ void lua_scripts::repl_cleanup (void) { AP::FS().unlink(REPL_DIRECTORY); } } + // Reset memory counters + allocated = 0; + deallocated = 0; } void lua_scripts::run(void) { bool succeeded_initial_load = false; + allocated = 0; + deallocated = 0; if (!_heap.available()) { GCS_SEND_TEXT(MAV_SEVERITY_CRITICAL, "Lua: Unable to allocate a heap"); @@ -511,8 +553,16 @@ void lua_scripts::run(void) { lua_atpanic(L, atpanic); load_generated_bindings(L); + const int loaded_mem = allocated - deallocated; + allocated = 0; + deallocated = 0; + +#if defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 + if (loaded_mem != (lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0))) { + AP_HAL::panic("Lua: state memory calc does not match"); + } +#endif #ifndef HAL_CONSOLE_DISABLED - const int loaded_mem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); DEV_PRINTF("Lua: State memory usage: %i + %i\n", inital_mem, loaded_mem - inital_mem); #endif @@ -549,53 +599,87 @@ void lua_scripts::run(void) { if (lua_gettop(L) != 0) { AP_HAL::panic("Lua: Stack should be empty before running scripts"); } + if ((allocated != 0) || (deallocated != 0)) { + AP_HAL::panic("Lua: unexpected memory use in loop"); + } #endif // defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 if (scripts != nullptr) { #if defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 - // Sanity check that the scripts list is ordered correctly - script_info *sanity = scripts; - while (sanity->next != nullptr) { - if (sanity->next_run_ms > sanity->next->next_run_ms) { - AP_HAL::panic("Lua: Script tasking order has been violated"); - } - sanity = sanity->next; - } + // Sanity check that the scripts list is ordered correctly + // Check total memory adds up + script_info *sanity = scripts; + int total_mem = loaded_mem + sanity->memory; + while (sanity->next != nullptr) { + if (sanity->next_run_ms > sanity->next->next_run_ms) { + AP_HAL::panic("Lua: Script tasking order has been violated"); + } + sanity = sanity->next; + total_mem += sanity->memory; + } + const int lua_total_mem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); + if ((allocated != 0) || (deallocated != 0)) { + AP_HAL::panic("Lua: unexpected memory use in total"); + } + if (total_mem != lua_total_mem) { + AP_HAL::panic("Lua: total memory sum error (%i vs %i)", total_mem, lua_total_mem); + } #endif // defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 + script_info *script_to_run = scripts; + // compute delay time uint64_t now_ms = AP_HAL::millis64(); - if (now_ms < scripts->next_run_ms) { - hal.scheduler->delay(scripts->next_run_ms - now_ms); + if (now_ms < script_to_run->next_run_ms) { + hal.scheduler->delay(script_to_run->next_run_ms - now_ms); } if ((_debug_options.get() & uint8_t(DebugLevel::RUNTIME_MSG)) != 0) { - GCS_SEND_TEXT(MAV_SEVERITY_DEBUG, "Lua: Running %s", scripts->name); + GCS_SEND_TEXT(MAV_SEVERITY_DEBUG, "Lua: Running %s", script_to_run->name); } - // copy name for logging, cant do it after as script reschedule moves the pointers - const char * script_name = scripts->name; #if DISABLE_INTERRUPTS_FOR_SCRIPT_RUN void *istate = hal.scheduler->disable_interrupts_save(); #endif - +#if defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 const int startMem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); +#endif const uint32_t loadEnd = AP_HAL::micros(); run_next_script(L); - const uint32_t runEnd = AP_HAL::micros(); +#if defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 + int MidMem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); + if ((MidMem - startMem) != int(allocated - deallocated)) { + AP_HAL::panic("Lua: mid memory calc does not match"); + } +#endif + + // garbage collect after each script, this shouldn't matter, but seems to resolve a memory leak + lua_gc(L, LUA_GCCOLLECT, 0); + const int endMem = lua_gc(L, LUA_GCCOUNT, 0) * 1024 + lua_gc(L, LUA_GCCOUNTB, 0); +#if defined(AP_SCRIPTING_CHECKS) && AP_SCRIPTING_CHECKS >= 1 + if ((endMem - startMem) != int(allocated - deallocated)) { + AP_HAL::panic("Lua: end memory calc does not match"); + } +#endif + + const uint32_t runEnd = AP_HAL::micros(); #if DISABLE_INTERRUPTS_FOR_SCRIPT_RUN hal.scheduler->restore_interrupts(istate); #endif - update_stats(script_name, runEnd - loadEnd, endMem, endMem - startMem); - + if (script_to_run != nullptr) { + // If script crashed in `run_next_script` it will be nullptr + script_to_run->memory += allocated - deallocated; + update_stats(script_to_run->name, runEnd - loadEnd, endMem, script_to_run->memory, allocated); + } - // garbage collect after each script, this shouldn't matter, but seems to resolve a memory leak - lua_gc(L, LUA_GCCOLLECT, 0); + // Re-zero count for next script + allocated = 0; + deallocated = 0; } else { if ((_debug_options.get() & uint8_t(DebugLevel::NO_SCRIPTS_TO_RUN)) != 0) { diff --git a/libraries/AP_Scripting/lua_scripts.h b/libraries/AP_Scripting/lua_scripts.h index 04001f39bfb60..80f98e4e2ed01 100644 --- a/libraries/AP_Scripting/lua_scripts.h +++ b/libraries/AP_Scripting/lua_scripts.h @@ -67,6 +67,7 @@ class lua_scripts uint64_t next_run_ms; // time (in milliseconds) the script should next be run at uint32_t crc; // crc32 checksum char *name; // filename for the script // FIXME: This information should be available from Lua + size_t memory; // Amount of memory being used by this script script_info *next; } script_info; @@ -117,7 +118,7 @@ class lua_scripts static MultiHeap _heap; // helper for print and log of runtime stats - void update_stats(const char *name, uint32_t run_time, int total_mem, int run_mem); + void update_stats(const char *name, uint32_t run_time, int total_mem, int script_mem, int run_allocation); // must be static for use in atpanic static void print_error(MAV_SEVERITY severity); @@ -125,6 +126,8 @@ class lua_scripts static HAL_Semaphore error_msg_buf_sem; static uint8_t print_error_count; static uint32_t last_print_ms; + static size_t allocated; + static size_t deallocated; int current_ref; // XOR of crc32 of running scripts