From 8a181871038f77ed0e7e0dfe0f4d2ebf3f54bc19 Mon Sep 17 00:00:00 2001 From: masterdraco Date: Sat, 26 Sep 2026 11:19:35 +0200 Subject: [PATCH] =?UTF-8?q?feat(perf):=20indbygget=20profiler=20=E2=80=94?= =?UTF-8?q?=20m=C3=A5ler=20alle=20indgange=20(hooks,=20update,=20GUI),=20l?= =?UTF-8?q?ogger=20top-6=20pr.=20minut=20ved=20>=202=20ms?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- FS25_ADSmartPickup/adProfiler.lua | 121 +++++++++++++++++++++++++++ FS25_ADSmartPickup/adSmartPickup.lua | 5 ++ FS25_ADSmartPickup/modDesc.xml | 1 + tests/test_adProfiler.lua | 42 ++++++++++ 4 files changed, 169 insertions(+) create mode 100644 FS25_ADSmartPickup/adProfiler.lua create mode 100644 tests/test_adProfiler.lua diff --git a/FS25_ADSmartPickup/adProfiler.lua b/FS25_ADSmartPickup/adProfiler.lua new file mode 100644 index 0000000..fa092fc --- /dev/null +++ b/FS25_ADSmartPickup/adProfiler.lua @@ -0,0 +1,121 @@ +-- AD Profiler +-- Måler Smart Pickups indgange (AutoDrive-hooks, update-løkken, GUI) i spillet: kald, samlet tid og det +-- værste enkeltkald pr. minut, plus det værste frame i alt. Tager noget over REPORT_MIN_MS, skrives top-listen +-- i log.txt ("ADSmartPickup: profil …"), så et hak kan føres tilbage til præcis hvilken del der gjorde det. +-- Indpakningen sker på modul-tabellernes felter; hooksene slår funktionerne op ved hvert kald, så de måles. + +ADProfiler = {} + +ADProfiler.WINDOW_MS = 60000 +ADProfiler.REPORT_MIN_MS = 2 +ADProfiler.TOP = 6 +ADProfiler.stats = {} +ADProfiler.frameMs = 0 +ADProfiler.worstFrameMs = 0 +ADProfiler.windowStart = nil +ADProfiler.depth = 0 +ADProfiler.installed = false + +function ADProfiler.clock() + local ok, ms = pcall(function() return netGetTime() end) + if ok and type(ms) == "number" then return ms end + return nil +end + +local function record(name, started, ...) + local finished = ADProfiler.clock() + ADProfiler.depth = ADProfiler.depth - 1 + if started ~= nil and finished ~= nil then + local spent = finished - started + local stat = ADProfiler.stats[name] + if stat == nil then + stat = {calls = 0, total = 0, max = 0} + ADProfiler.stats[name] = stat + end + stat.calls = stat.calls + 1 + stat.total = stat.total + spent + if spent > stat.max then stat.max = spent end + -- kun yderste måling tæller i frame-summen (indlejrede måles også hver for sig) + if ADProfiler.depth == 0 then ADProfiler.frameMs = ADProfiler.frameMs + spent end + end + return ... +end + +-- Pak tbl[key] ind under navnet name (gør intet hvis funktionen ikke findes). +function ADProfiler.wrap(tbl, key, name) + if type(tbl) ~= "table" or type(tbl[key]) ~= "function" then return end + local original = tbl[key] + tbl[key] = function(...) + ADProfiler.depth = ADProfiler.depth + 1 + return record(name, ADProfiler.clock(), original(...)) + end +end + +-- Kaldes én gang pr. frame fra ADSmartPickup:update: afslutter frame-summen og rapporterer pr. minut. +function ADProfiler.frame(now) + if ADProfiler.frameMs > ADProfiler.worstFrameMs then ADProfiler.worstFrameMs = ADProfiler.frameMs end + ADProfiler.frameMs = 0 + -- (en fejl i en indpakket funktion springer record over; dybden nulstilles derfor hvert frame) + ADProfiler.depth = 0 + ADProfiler.windowStart = ADProfiler.windowStart or now + if now - ADProfiler.windowStart < ADProfiler.WINDOW_MS then return end + ADProfiler.report() + ADProfiler.windowStart = now +end + +function ADProfiler.report() + local rows = {} + for name, stat in pairs(ADProfiler.stats) do + table.insert(rows, {name = name, stat = stat}) + end + table.sort(rows, function(a, b) return a.stat.max > b.stat.max end) + local worst = rows[1] ~= nil and rows[1].stat.max or 0 + if worst >= ADProfiler.REPORT_MIN_MS or ADProfiler.worstFrameMs >= ADProfiler.REPORT_MIN_MS then + local parts = {} + for index = 1, math.min(ADProfiler.TOP, #rows) do + local stat = rows[index].stat + table.insert(parts, string.format("%s max %.1f ms (%d kald, i alt %.0f ms)", rows[index].name, stat.max, stat.calls, stat.total)) + end + Logging.info("ADSmartPickup: profil sidste minut — værste frame %.1f ms: %s", ADProfiler.worstFrameMs, table.concat(parts, "; ")) + end + ADProfiler.stats = {} + ADProfiler.worstFrameMs = 0 +end + +-- Indpak alle kendte indgange. Kaldes én gang efter at hooksene er installeret. +function ADProfiler.install() + if ADProfiler.installed then return end + ADProfiler.installed = true + local targets = { + {ADUnloadWait, "beforeUpdate", "aflæsning/Wait (pr. vogn)"}, + {ADUnloadWait, "adoptOrphans", "genoptag ventende"}, + {ADUnloadWait, "releaseInactive", "slip standsede"}, + {ADOutbound, "beforeLoadUpdate", "udkørsel pålæsning (pr. vogn)"}, + {ADOutbound, "beforeUnloadUpdate", "udkørsel aflæsning (pr. vogn)"}, + {ADOutbound, "beforeLoadFinished", "udkørsel runde"}, + {ADOutbound, "choosePickup", "udkørsel turvalg"}, + {ADOutbound, "holdSupplyVehicle", "forsyning hold"}, + {ADOutbound, "releaseInactive", "udkørsel slip"}, + {ADLoadSwap, "tryFromWait", "læs-bytte fra Wait"}, + {ADSmartPickup, "shouldWaitForLoading", "vent ved pålæsning"}, + {ADSmartPickup, "choosePickup", "forsyning kildevalg"}, + {ADSmartPickup, "findSupplyPickup", "forsyning kildesøgning"}, + {ADRunsController, "applyVehicleNames", "traktornavne"}, + {ADFieldJobs, "tick", "markarbejde tick"}, + {ADFields, "scanStep", "markscanning"}, + {ADFieldWork, "follow", "markarbejde sæt"}, + {ADFieldWork, "dispatch", "markarbejde udsendelse"}, + {ADFieldWork, "getRigs", "markflåde"}, + {ADBuildings, "list", "bygningsliste"}, + {ADSources, "getFarmInventory", "gårdens lagre"}, + {ADWaitPool, "hasRouteTo", "rutetjek"}, + {ADWaitPool, "hasRouteBothWays", "rutetjek frem+tilbage"}, + } + for _, target in ipairs(targets) do + ADProfiler.wrap(target[1], target[2], target[3]) + end + if SmartPickupFrame ~= nil then + ADProfiler.wrap(SmartPickupFrame, "refreshLive", "menu opdatering") + ADProfiler.wrap(SmartPickupFrame, "rebuild", "menu genopbygning") + end +end diff --git a/FS25_ADSmartPickup/adSmartPickup.lua b/FS25_ADSmartPickup/adSmartPickup.lua index f312591..1a047bc 100644 --- a/FS25_ADSmartPickup/adSmartPickup.lua +++ b/FS25_ADSmartPickup/adSmartPickup.lua @@ -1184,11 +1184,16 @@ function ADSmartPickup:loadMap() end function ADSmartPickup:update(dt) + if ADProfiler ~= nil and ADProfiler.installed then + local now = ADProfiler.clock() + if now ~= nil then pcall(ADProfiler.frame, now) end + end if not isHooked then local adEnv = getAutoDriveEnv() if adEnv ~= nil and g_currentMission ~= nil and g_currentMission.storageSystem ~= nil then installHook(adEnv) isHooked = true + if ADProfiler ~= nil then pcall(ADProfiler.install) end if ADRunsController ~= nil then pcall(ADRunsController.load, adEnv) pcall(ADRunsController.installSaveHook) diff --git a/FS25_ADSmartPickup/modDesc.xml b/FS25_ADSmartPickup/modDesc.xml index 1ca7da9..ef05a4d 100644 --- a/FS25_ADSmartPickup/modDesc.xml +++ b/FS25_ADSmartPickup/modDesc.xml @@ -34,6 +34,7 @@ + diff --git a/tests/test_adProfiler.lua b/tests/test_adProfiler.lua new file mode 100644 index 0000000..0f5cb38 --- /dev/null +++ b/tests/test_adProfiler.lua @@ -0,0 +1,42 @@ +-- Kør: luajit tests/test_adProfiler.lua (fra repo-roden) +local failures = 0 +local function check(name, actual, expected) + if actual == expected then print("OK " .. name) else + failures = failures + 1 + print(string.format("FAIL %s: forventede %s, fik %s", name, tostring(expected), tostring(actual))) + end +end +local lines = {} +Logging = {info = function(fmt, ...) table.insert(lines, string.format(fmt, ...)) end} +local clock = 0 +function netGetTime() return clock end +dofile("FS25_ADSmartPickup/adProfiler.lua") + +local Module = {} +function Module.slow(a, b) clock = clock + 5; return a + b, "ok" end +function Module.fast() clock = clock + 0.1 end +ADProfiler.wrap(Module, "slow", "langsom") +ADProfiler.wrap(Module, "fast", "hurtig") +local sum, text = Module.slow(2, 3) +check("P1 returværdier bevares", sum, 5); check("P1 anden returværdi", text, "ok") +Module.fast() +check("P2 kald talt", ADProfiler.stats["langsom"].calls, 1) +check("P2 max", ADProfiler.stats["langsom"].max, 5) +ADProfiler.frame(0) +check("P3 værste frame", ADProfiler.worstFrameMs, 5.1) +ADProfiler.frame(61000) +check("P4 rapport skrevet", #lines, 1) +check("P4 langsom først", lines[1]:find("langsom max 5.0", 1, true) ~= nil, true) +check("P4 nulstillet", next(ADProfiler.stats), nil) +-- intet over 2 ms -> ingen rapport +Module.fast(); ADProfiler.frame(62000); ADProfiler.frame(130000) +check("P5 stille minut -> ingen linje", #lines, 1) +-- fejl i indpakket funktion: dybden nulstilles næste frame +function Module.boom() error("x") end +ADProfiler.wrap(Module, "boom", "fejl") +pcall(Module.boom) +ADProfiler.frame(131000) +check("P6 dybde nulstillet", ADProfiler.depth, 0) + +print(failures == 0 and "\nALLE TESTS OK" or ("\n" .. failures .. " FEJL")) +os.exit(failures == 0 and 0 or 1)