Apply Patch

GentleGC.lua

@@ -89,6 +89,10 @@ local pauseAvg = nil       -- ms, moving average of our own collections
 local careful = false
 local extByName = {}       -- session: collections run by other addons, by addon name
 local extSeq, extMs, extName = 0, 0, nil   -- last external collection (freeze detector)
+local thrByName, thrCount = {}, 0          -- session: threshold changes by other addons, by name
+local wrappedBy = false    -- addon(s) whose Lua wrapper our collectgarbage passes through (found at load)
+local intercepted, interceptWarned = 0, false   -- our collections that didn't run normally
+local pn, px, py, pxx, pxy, pxMin, pxMax = 0, 0, 0, 0, 0, nil, nil   -- pause (ms) vs MB freed, own collections
 do
   local used, threshold = gcinfo()
   -- before any collection we can only assume the stock 2x ratio; the first
@@ -195,6 +199,18 @@ local function CountExternal(name, ms, freed)
   end
 end
 
+-- Someone set the threshold without collecting (collectgarbage(n) with n
+-- above the heap). Logged so a threshold left just above the heap - which
+-- makes the next collection come almost at once - can be traced to an addon.
+local function NoteThreshold(name, threshold, used)
+  name = name or "unknown addon"
+  thrByName[name] = (thrByName[name] or 0) + 1
+  thrCount = thrCount + 1
+  if DebugLevel() >= 2 then
+    Msg(format("threshold set to %.1fmb by %s (heap %.1fmb)", MB(threshold), name, MB(used)))
+  end
+end
+
 -- After someone else's collection the collector has set a fresh threshold,
 -- and any raised combat threshold is gone: in combat, grant the headroom again.
 local function AfterForeignCollection()
@@ -211,21 +227,27 @@ local function Sync()
   local used, threshold = gcinfo()
   -- the heap only shrinks through a collection, which may leave the
   -- threshold unchanged if live memory happens to be the same as before
-  if threshold == knownThreshold and used >= lastUsed - 1024 then Account(used); return end
+  if threshold == knownThreshold and used >= lastUsed then Account(used); return end
   local oldThreshold = knownThreshold
   knownThreshold = threshold
   if oldThreshold == 0 then Account(used); return end
 
-  if used < lastUsed - 1024 and GentleGCMemory and GentleGCMemory.measuring then
+  if GentleGCMemory and GentleGCMemory.measuring then
     -- the memory companion collecting between addons at the loading screen
-    liveKB = used
-    lastUsed = used
+    if used < lastUsed then
+      liveKB = used
+      lastUsed = used
+    else
+      Account(used)
+    end
     return
   end
 
-  if used < lastUsed - 1024 then
+  if used < lastUsed then
     local est = used
-    if ratioMin then est = math.min(used, math.floor(threshold / ratioMin)) end
+    -- a threshold left within 5% of the heap wasn't set by the collector's
+    -- own rule (at least 1.25x live), so it says nothing about live memory
+    if ratioMin and threshold >= used * 1.05 then est = math.min(used, math.floor(threshold / ratioMin)) end
     liveKB = est
     if lastUsed < oldThreshold * 0.9 then
       AddAlloc(used - est)
@@ -246,6 +268,7 @@ local function Sync()
   else
     -- threshold set by someone without collecting; live memory is unchanged
     Account(used)
+    NoteThreshold(nil, threshold, used)
     if inCombat then EnterCombatThreshold() end
   end
 end
@@ -302,11 +325,26 @@ local function Collect(reason)
   local ms = StopTimer(t0)
   local after, threshold = gcinfo()
 
-  if threshold == thresholdBefore and after >= before - 256 then
-    -- nothing happened: an addon that wraps collectgarbage blocked the call
+  local blocked = threshold == thresholdBefore and after >= before - 256
+  -- a full collection always leaves the threshold well above the heap (the
+  -- client's rule is at least 1.25x live); within 5% means collectgarbage()
+  -- was turned into something else by an addon that wraps it
+  local abnormal = not blocked and after > 1024 and threshold < after * 1.05
+  if blocked or abnormal then
     lastGC = GetTime()
-    if DebugLevel() >= 1 then
-      Msg(reason .. ": collection did not run (another addon blocks collectgarbage)")
+    liveKB = after                     -- assume nothing to free: don't retry at once
+    lastUsed = after
+    knownThreshold = threshold
+    intercepted = intercepted + 1
+    local who = wrappedBy and ("by " .. wrappedBy) or "by an addon that loaded before GentleGC"
+    if not interceptWarned then
+      interceptWarned = true
+      Msg(format("collectgarbage() %s: heap %.1fmb, threshold left at %.1fmb. It is wrapped %s, "
+        .. "so GentleGC can't collect at quiet moments while that is active. Turn off that addon's "
+        .. "garbage-collection option, or disable it.",
+        blocked and "did not run" or "didn't run a normal collection", MB(after), MB(threshold), who))
+    elseif DebugLevel() >= 2 then
+      Msg(format("%s: collectgarbage() didn't run a normal collection (threshold left at %.1fmb)", reason, MB(threshold)))
     end
     return
   end
@@ -321,6 +359,11 @@ local function Collect(reason)
   ownCollectSeq, ownCollectMs, ownCollectReason = ownCollectSeq + 1, ms, reason
 
   local freed = before - after
+  -- pause against garbage freed: on this client freeing may be most of the cost
+  local x = MB(math.max(0, freed))
+  pn, px, py, pxx, pxy = pn + 1, px + x, py + ms, pxx + x * x, pxy + x * ms
+  if not pxMin or x < pxMin then pxMin = x end
+  if not pxMax or x > pxMax then pxMax = x end
   for _, s in ipairs({ period, total }) do
     s.count = s.count + 1
     s.freed = s.freed + freed
@@ -432,12 +475,34 @@ local function WrappedCollect(a, b)
   elseif threshold ~= knownThreshold then
     knownThreshold = threshold
     Account(after)
+    NoteThreshold(CallerAddon(), threshold, after)
     if inCombat then EnterCombatThreshold() end
   end
   return r
 end
 
+-- Which addons' Lua wrappers does our own collectgarbage pass through? Call
+-- it with an invalid argument: the real collector raises an error before
+-- doing anything, and the stack at that moment shows every addon file the
+-- call went through. No collection happens.
+local function FindWrappers()
+  if not (debugstack and xpcall) then return false end
+  local found, seen = nil, {}
+  xpcall(function() rawCollect({}) end, function()
+    local ok, stack = pcall(debugstack)
+    if ok and type(stack) == "string" then
+      for name in gfind(stack, "[Aa][Dd][Dd][Oo][Nn][Ss][\\/]([^\\/]+)[\\/]") do
+        if name ~= ADDON and not seen[name] then
+          seen[name] = true
+          found = found and (found .. ", " .. name) or name
+        end
+      end
+    end
+  end)
+  return found or false
+end
 if type(rawCollect) == "function" then
+  wrappedBy = FindWrappers()
   collectgarbage = WrappedCollect
 end
 
@@ -447,7 +512,7 @@ end
 local sampleFrame             -- created on ADDON_LOADED
 local function SampleOnUpdate()
   local used, threshold = gcinfo()
-  if threshold ~= knownThreshold or used < lastUsed - 1024 then
+  if threshold ~= knownThreshold or used < lastUsed then
     Sync()
   else
     AddAlloc(used - lastUsed)
@@ -533,9 +598,12 @@ local function Check(dt)
     end
 
     local used, threshold = gcinfo()
-    if used >= PressurePointKB(threshold) and GetTime() - lastGC >= 5 then
+    if used >= PressurePointKB(threshold) and GetTime() - lastGC >= 5
+        and GarbageKB() >= math.max(1024, liveKB / 100) then
       -- The automatic collector is about to fire anyway and would cost the
       -- same pause, so collect now, out of combat, without the garbage minimum.
+      -- But not when there's next to nothing to free: that happens when an
+      -- addon has set the threshold just above the heap.
       Collect("pressure")
     elseif careful then
       -- collections are slow enough to see: wait for a loading screen, NPC
@@ -920,6 +988,35 @@ local OPTIONS = {
   allocwarn = "allocWarnMB",
 }
 
+-- Other addons' collections and thresholds, wrappers, and the pause model
+-- (split from PrintStatus: Lua 5.0 allows a function only 32 upvalues).
+local function PrintDiagnostics()
+  if total.ext > 0 then
+    local parts = {}
+    for name, n in pairs(extByName) do table.insert(parts, name .. " " .. n) end
+    table.sort(parts)
+    Msg(format("by other addons: %d (%d in combat) - %s", total.ext, total.extCombat, table.concat(parts, ", ")))
+  end
+  if wrappedBy or intercepted > 0 then
+    Msg(format("collectgarbage is wrapped by %s; %d of GentleGC's collections didn't run normally",
+      wrappedBy or "an unknown addon", intercepted))
+  end
+  if thrCount > 0 then
+    local parts = {}
+    for name, n in pairs(thrByName) do table.insert(parts, name .. " " .. n) end
+    table.sort(parts)
+    Msg(format("threshold set without collecting: %d - %s", thrCount, table.concat(parts, ", ")))
+  end
+  if pn >= 5 and pxMax - pxMin >= 5 then
+    local b = (pn * pxy - px * py) / (pn * pxx - px * px)
+    local a = (py - b * px) / pn
+    Msg(format("pause vs garbage freed (%d collections): ~%dms + %.1fms per MB freed%s",
+      pn, math.max(0, a), b, (DebugLevel() == 0 and db.hitchMs == 0) and " (timed in ~15ms steps; /ggc debug 1 times them exactly)" or ""))
+  elseif pn > 0 then
+    Msg(format("pause vs garbage freed: not enough data yet (%d collections; needs 5, with freed amounts at least 5mb apart)", pn))
+  end
+end
+
 local function PrintStatus()
   Sync()
   local used, threshold = gcinfo()
@@ -940,12 +1037,7 @@ local function PrintStatus()
   Msg(format("session: %d collections, %d skipped, freed %.1fmb, avg %dms, worst %dms; %d automatic (%d in combat)",
     total.count, total.skipped, MB(total.freed),
     total.count > 0 and total.ms / total.count or 0, total.worst, total.auto, total.autoCombat))
-  if total.ext > 0 then
-    local parts = {}
-    for name, n in pairs(extByName) do table.insert(parts, name .. " " .. n) end
-    table.sort(parts)
-    Msg(format("by other addons: %d (%d in combat) - %s", total.ext, total.extCombat, table.concat(parts, ", ")))
-  end
+  PrintDiagnostics()
   local up = GetTime() - loadTime
   if up >= 60 then
     Msg(format("garbage created: %.1f MB/s now (30 s average), %.1f MB/s this session",

GentleGC.toc

@@ -2,7 +2,7 @@
 ## Title: Gentle GC
 ## Notes: Schedules Lua garbage collection for moments you won't notice
 ## Author: Weird Vibes (MarcelineVQ); forks by TheRealFayz, jrc13245
-## Version: 2.5
+## Version: 2.6
 ## SavedVariables: GentleGCDB
 
 GentleGC.lua

tests/test_threshold.lua

@@ -0,0 +1,166 @@
+-- Threshold changes by other addons, the pressure guard, and the pause vs
+-- garbage-freed estimate. Simulates the 1.12 client's collector (1.25x).
+-- Run: lua5.0 tests/test_threshold.lua GentleGC.lua
+format = string.format
+local now = 1000
+function GetTime() return now end
+function UnitAffectingCombat() return false end
+function UnitIsAFK() return false end
+local log = {}
+DEFAULT_CHAT_FRAME = { AddMessage = function(_, m) table.insert(log, m); print("  " .. m) end }
+SlashCmdList = {}
+FRAMES = {}
+function CreateFrame()
+  local f = { scripts = {} }
+  function f:RegisterEvent() end
+  function f:UnregisterEvent() end
+  function f:SetScript(k, fn) self.scripts[k] = fn end
+  table.insert(FRAMES, f)
+  return f
+end
+local caller = nil
+function debugstack()
+  local s = "Interface\\AddOns\\GentleGC\\GentleGC.lua:400: in function `WrappedCollect'\n"
+  if caller then s = s .. "Interface\\AddOns\\" .. caller .. "\\core.lua:12: in function `x'\n" end
+  return s
+end
+
+-- the client's collector: full collections leave the threshold at 1.25x live,
+-- and take 10 ms + 8 ms per MB freed (simulated on the clock)
+local origCG = collectgarbage
+local function setThreshold() local u = gcinfo(); origCG(math.floor(u * 1.25)) end
+local timed = false
+collectgarbage = function(n)
+  if n == nil or n == 0 then
+    local before = gcinfo()
+    origCG(); setThreshold()
+    if timed then now = now + 0.010 + 0.008 * (before - gcinfo()) / 1024 end
+  else
+    origCG(n)
+  end
+end
+local unwrapped = collectgarbage   -- what an addon holds if it loaded before us
+
+LIVE = {}
+for i = 1, 300000 do LIVE[i] = { i } end
+origCG(); setThreshold()
+
+dofile(arg[1])
+local F = FRAMES[1]
+event, arg1 = "ADDON_LOADED", "GentleGC"; this = F; F.scripts.OnEvent()
+local SF = FRAMES[4]
+local cmd = SlashCmdList.GENTLEGC
+cmd("debug 2")
+
+local function count(pat) local n = 0; for _, m in ipairs(log) do if string.find(m, pat) then n = n + 1 end end; return n end
+local function lastMatch(pat) for i = table.getn(log), 1, -1 do if string.find(log[i], pat) then return log[i] end end; return "" end
+local function check(name, c) print((c and "PASS " or "FAIL ") .. name); if not c then FAILED = true end end
+local function frame(dt) now = now + dt; SF.scripts.OnUpdate(); arg1 = dt; this = F; F.scripts.OnUpdate() end
+local function seconds(n) for i = 1, n * 10 do frame(0.1) end end
+local function garbageMB(mb) local t = {}; for i = 1, mb * 7000 do t[i] = { i, i } end end
+
+print("1. the login case: an addon leaves the threshold just above the heap")
+cmd("now")                       -- ratio measured, live known
+seconds(40)
+local used = gcinfo()
+unwrapped(used + 300)            -- threshold 0.3 MB above the heap, no collection
+seconds(6)
+check("logged as a threshold change, not a collection", string.find(lastMatch("threshold set to"), "by unknown addon") ~= nil)
+check("no pressure collection for nothing", count("pressure:") == 0)
+cmd("status")
+check("status lists it", string.find(lastMatch("threshold set without collecting"), "unknown addon 1") ~= nil)
+
+print("2. a wrapped addon setting the threshold is named")
+caller = "FpsWatch"
+collectgarbage(gcinfo() + 500)
+caller = nil
+check("named in the log", string.find(lastMatch("threshold set to"), "by FpsWatch") ~= nil)
+origCG(); setThreshold()         -- the game collects at that threshold
+seconds(2)
+
+print("3. a game collection that frees under 1 MB is still a collection")
+local autoBefore = count("automatic GC detected")
+do
+  local _, t = gcinfo()
+  local junk, i = {}, 0
+  while gcinfo() < t * 0.995 do
+    for k = 1, 200 do i = i + 1; junk[i] = { i } end
+    SF.scripts.OnUpdate()
+  end
+  junk = nil
+end
+origCG(); setThreshold()
+seconds(1)
+check("detected as automatic", count("automatic GC detected") == autoBefore + 1)
+check("not reported as a threshold change", count("threshold set to") == 2)
+
+print("4. pressure with real garbage still collects")
+now = now + 40
+local l, t = gcinfo()
+do
+  local junk, i = {}, 0
+  while gcinfo() < l + (t - l) * 0.85 do
+    for k = 1, 300 do i = i + 1; junk[i] = { i } end
+    if i > 20000 then junk = {}; i = 0 end
+    SF.scripts.OnUpdate()
+  end
+end
+seconds(2)
+check("pressure collection ran", count("pressure:") == 1)
+check("it freed garbage", string.find(lastMatch("pressure:"), "freed [1-9]") ~= nil)
+
+print("5. pause vs garbage freed")
+timed = true
+cmd("slow 0")
+for k, mb in ipairs({ 1, 4, 8, 12, 16, 20, 25 }) do
+  now = now + 40
+  origCG(gcinfo() + 64 * 1024)   -- room for this much garbage without the test Lua collecting on its own
+  seconds(1)
+  garbageMB(mb)
+  cmd("now")
+end
+cmd("status")
+local line = lastMatch("pause vs garbage freed")
+local _, _, a, b = string.find(line, "~(%-?%d+)ms %+ ([%d%.]+)ms per MB")
+a, b = tonumber(a), tonumber(b)
+check("model shown", a ~= nil and b ~= nil)
+check("fixed part ~10 ms", a and a >= 0 and a <= 25)
+check("per-MB part ~8 ms", b and b >= 6.5 and b <= 9.5)
+
+print("6. an addon loaded before GentleGC turns collectgarbage() into 'threshold just above the heap'")
+-- (the 0.0-0.3 MB "pressure" collections every few seconds)
+FRAMES = {}
+log = {}
+DEFAULT_CHAT_FRAME = { AddMessage = function(_, m) table.insert(log, m); print("  " .. m) end }
+GentleGCDB = nil
+SlashCmdList = {}
+local client = collectgarbage
+collectgarbage = function(n)
+  caller = "FpsWatch"            -- this wrapper's frame is on the stack while it runs
+  if n == nil or n == 0 then
+    client(gcinfo() + 200)       -- no collection: threshold 0.2 MB above the heap
+  else
+    client(n)
+  end
+  caller = nil
+end
+timed = false
+origCG(); setThreshold()
+dofile(arg[1])
+F = FRAMES[1]
+event, arg1 = "ADDON_LOADED", "GentleGC"; this = F; F.scripts.OnEvent()
+SF = FRAMES[4]
+cmd = SlashCmdList.GENTLEGC
+cmd("debug 1")
+garbageMB(6)
+cmd("now")
+check("reported once", count("didn't run a normal collection") == 1)
+check("names the wrapping addon", string.find(lastMatch("didn't run a normal collection"), "wrapped by FpsWatch") ~= nil)
+seconds(30)
+check("no repeated pressure attempts", count("pressure:") == 0)
+cmd("status")
+check("status shows the wrapper", string.find(lastMatch("collectgarbage is wrapped"), "by FpsWatch; 1 of") ~= nil)
+check("not counted as a collection", string.find(lastMatch("session:"), "0 collections") ~= nil)
+check("ratio not learned from it", count("not measured yet") == 1)
+
+print(FAILED and "SOME TESTS FAILED" or "ALL TESTS PASSED")