Closed gbrayut closed 7 years ago
Can reproduce on windows 10:
=== RUN TestMemoryWMI
Total Iterations: 5000
No panics mean it succeeded. Other errors are OK. Memory should stabilize after ~1500 iterations.
Time: 0s Count: 0 Private Memory: 15.2MB MemStats.Alloc: 2.6MB MemStats.TotalAlloc: 26.4MB
Time: 16s Count: 250 Private Memory: 15.9MB MemStats.Alloc: 0.4MB MemStats.TotalAlloc: 42.6MB
Time: 33s Count: 500 Private Memory: 16.6MB MemStats.Alloc: 1.3MB MemStats.TotalAlloc: 58.1MB
Time: 51s Count: 750 Private Memory: 17.1MB MemStats.Alloc: 3.4MB MemStats.TotalAlloc: 74.8MB
Time: 69s Count: 1000 Private Memory: 17.8MB MemStats.Alloc: 1.8MB MemStats.TotalAlloc: 91.5MB
Time: 87s Count: 1250 Private Memory: 19.3MB MemStats.Alloc: 0.3MB MemStats.TotalAlloc: 108.2MB
Time: 104s Count: 1500 Private Memory: 19.7MB MemStats.Alloc: 1.5MB MemStats.TotalAlloc: 123.8MB
Time: 121s Count: 1750 Private Memory: 20.5MB MemStats.Alloc: 2.6MB MemStats.TotalAlloc: 139.6MB
Time: 135s Count: 2000 Private Memory: 20.8MB MemStats.Alloc: 2.6MB MemStats.TotalAlloc: 154.1MB
Time: 155s Count: 2250 Private Memory: 21.1MB MemStats.Alloc: 2.9MB MemStats.TotalAlloc: 172.7MB
Time: 172s Count: 2500 Private Memory: 21.9MB MemStats.Alloc: 1.3MB MemStats.TotalAlloc: 189.1MB
Time: 189s Count: 2750 Private Memory: 22.5MB MemStats.Alloc: 3.2MB MemStats.TotalAlloc: 205.7MB
Time: 206s Count: 3000 Private Memory: 22.9MB MemStats.Alloc: 1.2MB MemStats.TotalAlloc: 222.0MB
Time: 222s Count: 3250 Private Memory: 23.4MB MemStats.Alloc: 2.9MB MemStats.TotalAlloc: 238.2MB
Time: 239s Count: 3500 Private Memory: 23.9MB MemStats.Alloc: 1.1MB MemStats.TotalAlloc: 254.7MB
Time: 255s Count: 3750 Private Memory: 24.5MB MemStats.Alloc: 1.8MB MemStats.TotalAlloc: 270.0MB
Time: 272s Count: 4000 Private Memory: 24.9MB MemStats.Alloc: 0.3MB MemStats.TotalAlloc: 286.6MB
Time: 288s Count: 4250 Private Memory: 25.4MB MemStats.Alloc: 1.3MB MemStats.TotalAlloc: 302.2MB
Time: 305s Count: 4500 Private Memory: 25.9MB MemStats.Alloc: 0.2MB MemStats.TotalAlloc: 319.4MB
Time: 321s Count: 4750 Private Memory: 26.5MB MemStats.Alloc: 1.5MB MemStats.TotalAlloc: 335.2MB
Final Private Memory: 27.1MB MemStats.Alloc: 2.0MB MemStats.TotalAlloc: 354.0MB
Good to know... The simple variant test worked fine, so tomorrow I plan on incrementaly testing the WMI code by adding each section one at a time.
Started a branch mem-narrow. Commented out most of query code. Added test output to each commit msg. Starts to look worse once I uncomment the QueryInterface part.
Cool... Another thing to try is add a test HTTP server and host the RSS file there so the OLE test loop is more like the WMI code path. Or just point it at a local server, but hitting the Internet 5000 times is probably a bad idea :-p
Reproduced leak using just ole calls: go test -run TestMemoryOLE -timeout 60m
Looks like unknown.QueryInterface(ole.IID_IDispatch) leaks ~1.5MB per 10k calls on Win10/Server2016. No memory leak on older operating systems.
PS C:\Users\gbray\go\src\github.com\StackExchange\wmi> go test -run TestMemoryOLE -timeout 60m
Benchmark Iterations: 50000000 (Memory should stabilize around 10MB to 12MB after ~2k full or 250k minimal)
Time: 0s Count: 0 Private Memory: 2.0MB MemStats.Alloc: 0.1MB MemStats.TotalAlloc: 0.1MB
Time: 13s Count: 2000 Private Memory: 4.0MB MemStats.Alloc: 1.3MB MemStats.TotalAlloc: 1.3MB
Time: 24s Count: 4000 Private Memory: 5.8MB MemStats.Alloc: 2.5MB MemStats.TotalAlloc: 2.5MB
Time: 37s Count: 6000 Private Memory: 7.3MB MemStats.Alloc: 3.6MB MemStats.TotalAlloc: 3.6MB
Time: 49s Count: 8000 Private Memory: 8.4MB MemStats.Alloc: 1.0MB MemStats.TotalAlloc: 4.8MB
Time: 61s Count: 10000 Private Memory: 9.1MB MemStats.Alloc: 2.1MB MemStats.TotalAlloc: 6.0MB
Time: 113s Count: 20000 Private Memory: 10.5MB MemStats.Alloc: 0.3MB MemStats.TotalAlloc: 11.8MB
Time: 170s Count: 30000 Private Memory: 12.2MB MemStats.Alloc: 2.2MB MemStats.TotalAlloc: 17.6MB
Time: 228s Count: 40000 Private Memory: 13.7MB MemStats.Alloc: 0.4MB MemStats.TotalAlloc: 23.4MB
Time: 293s Count: 50000 Private Memory: 15.3MB MemStats.Alloc: 2.3MB MemStats.TotalAlloc: 29.2MB
Time: 357s Count: 60000 Private Memory: 16.5MB MemStats.Alloc: 0.5MB MemStats.TotalAlloc: 35.0MB
Time: 422s Count: 70000 Private Memory: 18.1MB MemStats.Alloc: 2.4MB MemStats.TotalAlloc: 40.8MB
Time: 485s Count: 80000 Private Memory: 19.4MB MemStats.Alloc: 0.6MB MemStats.TotalAlloc: 46.6MB
Time: 554s Count: 90000 Private Memory: 20.9MB MemStats.Alloc: 2.6MB MemStats.TotalAlloc: 52.4MB
Time: 620s Count: 100000 Private Memory: 22.2MB MemStats.Alloc: 0.7MB MemStats.TotalAlloc: 58.3MB
Time: 740s Count: 120000 Private Memory: 25.0MB MemStats.Alloc: 0.9MB MemStats.TotalAlloc: 69.9MB
Time: 874s Count: 140000 Private Memory: 27.8MB MemStats.Alloc: 1.0MB MemStats.TotalAlloc: 81.5MB
Next will see if I can find a leak in the go-ole package, or if it is something in the OS.
I was not able to reproduce the issue in Python using the comtypes package, so I'll try filing an issue on the go-ole repo to ask for help tracking down the memory leak. I am not sure why it only happens on newer operating systems, but another approach may be to rework the collector to avoid IDispatch or have a dedicated thread/threadpool of WbemScripting.SWbemLocator "worker" objects and use channels to request queries and send responses to the collectors. The ELK stack has a WMIBeat which re-uses the same SWbemLocator object for multiple queries, and that approach may have other performance gains in addition to making it solving the COM memory leak.
I checked Telegraf to see what they did for WMI access and while they do reference Stackexchange/wmi in their Godeps file, the performance counter plugin uses a syscall to pdh.dll which takes a different syntax than our WMI queries.
Still hunting down a memory leak that only happens on Windows Server 2016. I can replicate it using
go test -run TestMemoryWMI
in this commit. 2016 uses ~20MB of private workingset memory, where as 2012 R2 only uses ~8.5M. Could not replicate in a simple OLE test... will keep investigating tomorrow.