Filtering child leaks... takes forever

delphi package - automated exception handling
Post Reply
altxt
Posts: 17
Joined: Thu Nov 24, 2016 3:47 pm

Filtering child leaks... takes forever

Post by altxt »

Hello madshi
I've been using madExcept for error reporting for a while now, and it works like a charm. Thank you very much for it!
Today I tried to use it to find memory leaks.
The project has 30MB worth of .pas files plus DevExpress and ODAC. It consists of an exe and a dozen of bpl's. I enabled "Report resource leaks" for the exe. The bpl's all only have "Enable madExcept" and "Link in function names and line numbers" checked.
If I run the exe, wait for the application to start, and then immediately close it, a small window appears, saying "Filtering child leaks". It took about 15 minutes for it to finish, and then a leak report appeared. It contained a number of strings and other small blocks, nothing to really worry about.
If I run the exe, do things that actually produce leaks, and then close it, the same "Filtering child leaks" phase takes WAY more time. It's been running for 5 hours now, and the progress bar is still at about 5%.
The process is using about 1.1GB of memory, according to Task manager.
Is there any way to speed up the leak reporting? Even at the expense of accuracy?
Delphi XE6, madExcept 4.0.16
madshi
Site Admin
Posts: 10754
Joined: Sun Mar 21, 2004 5:25 pm

Re: Filtering child leaks... takes forever

Post by madshi »

That sounds really bad. Are you running your EXE within the IDE when doing leak checking? I've found that running your EXE outside the IDE can speed things up dramatically. I'm not really sure why it's so extremely slow for you, though, in any case. Of course calculating the stack traces for each leak takes time, but if there are only a few leaks reported, anyway, it shouldn't take more than a couple of seconds to create the leak report.
altxt
Posts: 17
Joined: Thu Nov 24, 2016 3:47 pm

Re: Filtering child leaks... takes forever

Post by altxt »

I just tried to run the exe outside the IDE, and noticed no significant speed changes. For the empty run the generated report (.mbr) is 350K and has about 300 entries, is that enough to take 10-15 minutes? BTW some of the reported leaks are probably expected, such as TScreen or TApplication.
madshi
Site Admin
Posts: 10754
Joined: Sun Mar 21, 2004 5:25 pm

Re: Filtering child leaks... takes forever

Post by madshi »

That's about 2.5 seconds per leak. That's quite slow. How fast is your PC?

Can you try creating some test leaks in a simple brand new project, to see if you get the same slow performance there?
altxt
Posts: 17
Joined: Thu Nov 24, 2016 3:47 pm

Re: Filtering child leaks... takes forever

Post by altxt »

In a new project creating and leaking 3000 of empty TList<string> takes less than 3 seconds after program termination for the leak report to appear
200 lists each containing 200 strings take 12 seconds
300 lists each containing 300 strings take 55 seconds
Core i7-6700, 16GB RAM, Windows 8.1 x64, Win32 target platform

100 x 300 and 300 x 100 both take 8 seconds
And I noticed that in an empty project TApplication is not listed as leaked
madshi
Site Admin
Posts: 10754
Joined: Sun Mar 21, 2004 5:25 pm

Re: Filtering child leaks... takes forever

Post by madshi »

That seems more reasonable. I'm wondering why it's so much slower in your main app. To be honest, I'm not sure if there's anything I can do about it. It's unlikely that the performance is "wasted" somewhere, but I can't say for sure. FWIW, after those 15 minutes, are the callstacks of the leaks very complicated/long? Of course the longer the callstacks are, the longer it takes to calculate them.

The only thing coming to my mind right now would be to offer an alternative faster (but lower quality) callstack calculation method. madExcept already supports that, but only for exceptions, not for leaks as of yet.
altxt
Posts: 17
Joined: Thu Nov 24, 2016 3:47 pm

Re: Filtering child leaks... takes forever

Post by altxt »

The longest reported call stack is 25 lines, most are shorter.
Are call stacks really collected at leak detection time? I thought that was only possible during the program's runtime. And my suspicion for the slow leak analysis, assuming the "filtering child leaks" message was saying the truth, was that all leaked objects were compared to each other to see if one was a child of the other, and so had to be excluded from the report.
madshi
Site Admin
Posts: 10754
Joined: Sun Mar 21, 2004 5:25 pm

Re: Filtering child leaks... takes forever

Post by madshi »

Hmmmm... You're right. For some reason I selectively ignored the "filtering child leaks" part of your posts. That does suggest that it's not actually the stack traces which are the problem, but the checks if any leak is a "child" of another leak and thus should be ignored.

I suppose one easy "solution" would be to offer you an option to disable the checking for child leaks and instead simply show all leaks. Of course it would be nicer if I could instead simply make the child leak filtering faster. But it might be hard if I can't reproduce the slow behaviour here.

Can you upload the 15 minutes leak report you got? Maybe I can see why child leak filtering took so long if I can study the final leak report. If you don't want to publically upload it, you can send it to madshi (at) gmail (dot) com.
altxt
Posts: 17
Joined: Thu Nov 24, 2016 3:47 pm

Re: Filtering child leaks... takes forever

Post by altxt »

Mailed it
madshi
Site Admin
Posts: 10754
Joined: Sun Mar 21, 2004 5:25 pm

Re: Filtering child leaks... takes forever

Post by madshi »

Sorry for the late reply.

I've tried to recreate the issue by recreating some of the leaks I saw in your leak report. But I failed, it was always reasonably fast here.

So here's a test build of "madExcept32.dll" which should show a bit more detailed texts in the progress window than just "filtering child leaks":

http://madshi.net/madExcept32.rar

This should hopefully allow me to pinpoint more exactly which part of the code is causing the delay. Could you please run the 15 minute test again? Please let me know which exact text the progress bar shows when it gets stuck. Is it one text the whole time? Or does it hang with different texts for different time periods?

Thanks!
altxt
Posts: 17
Joined: Thu Nov 24, 2016 3:47 pm

Re: Filtering child leaks... takes forever

Post by altxt »

I upgraded to madExcept 4.0.20 and tried the same "15 minutes" empty scenario with and without the attached dll.
Both cases took ~5 min (can't say if it is due to an improvement in madExcept or I just fixed some leaks inadvertently)
When run with the attached dll, there is new text in the leak detection progress window. ~45 seconds is taken by "Checking Delphi object types", and the rest is "Process Delphi MM resources". There is also a third stage, something like "Preparing report", but it lightning fast, so I do not count it.

I'll now try to get a report on the real scenario.
Edit: unfortunately, on the real scenario the "Process Delphi MM resources" stage did not finish over night
altxt
Posts: 17
Joined: Thu Nov 24, 2016 3:47 pm

Re: Filtering child leaks... takes forever

Post by altxt »

I finally had time to work on finding and fixing the leaks, and I thought I'd share the lessons learned.

The main problem was that there were indeed many leaks, and there is no easy fix for that. I had to use the old-school method of manually isolating software components and fixing memory leaks in them individually.
When I was reasonably sure that components were leak-free, it was time to integrate them back. Unfortunately, there were still too many leaks, and madExcept's leak report did not reveal the source.

Then I tried FastMM, the full version with FullDebugMode. Its initial leak report before the fixes had been over 700 MB in size - a bit too much for analysis. But now it was much more useful. The key is in the message "filtering child leaks" that I've been looking at for too long. While it is showing, madExcept is doing the root cause analysis for all leaks it detected in order to report as few of them as possible. This is really helpful when you are missing a Free(). But when you are missing a FinalizePackage(), this is actually counterproductive. You have to see tons of leaks of objects that you totally free in your finalization sections to realize that maybe your finalizations aren't getting called, start digging and find out about UnloadPackage() and the like. FastMM helped with that.

I also tried EurekaLog which conveniently identified a case of use-after-free with a proper message and not just a generic AV, and AQTime standard which surprisingly did not bring anything.

Overall, in this case madExcept helped the most, although a setting for not filtering the leaks would have helped, and FastMM was the second-best.
madshi
Site Admin
Posts: 10754
Joined: Sun Mar 21, 2004 5:25 pm

Re: Filtering child leaks... takes forever

Post by madshi »

Thanks for the heads-up. I'll add an API to disable child leak filtering to a future build.
Post Reply