Recent

Author Topic: Why does it takes so long to build the heaptrace log for unfreed blocks  (Read 1189 times)

Pascal

  • Hero Member
  • *****
  • Posts: 783
I've enabled heaptrace log for Lazarus and have three blocks in my addon which have not been freed.
It takes about a minute to build the log when i quit Lazarus.
I've also noticed the slow creation for the stack trace in other apps.

Is there a way to speed this up?
laz trunk - fpc trunk 32bit - Windows 10 Pro x64 (1803)

Leledumbo

  • Hero Member
  • *****
  • Posts: 7984
  • Programming + Glam Metal + Tae Kwon Do = Me
Re: Why does it takes so long to build the heaptrace log for unfreed blocks
« Reply #1 on: September 21, 2018, 10:50:55 pm »
Can you add valgrind or gprof to the equation as this is kinda a specific case (e.g. it's always fast in my case)? I assume you don't set the heaptrace output (effectively redirecting its output to a physical file instead of standard output, which in this case, your storage can be the bottleneck).

Pascal

  • Hero Member
  • *****
  • Posts: 783
Re: Why does it takes so long to build the heaptrace log for unfreed blocks
« Reply #2 on: September 22, 2018, 06:24:03 am »
Output is redirected to file on SSD:
Code: Pascal  [Select]
  1. program Lazarus;
  2. ...
  3. begin
  4.   {$If Declared(UseHeapTrace)}
  5.   DeleteFile('lazarus-heaptrace.log');
  6.   SetHeapTraceOutput('lazarus-heaptrace.log');
  7.   // don't show empty heaptrc output
  8.   GlobalSkipIfNoLeaks := True;
  9.   {$endif}
  10.  

If i end Lazarus with for example 3 unfreed blocks it takes more than 30 s for the following output:
Code: Text  [Select]
  1. C:\freepascal\laz\lazarus.exe --no-splash-screen --started-by-startlazarus --primary-config-path=C:\freepascal\Config\i386 --force-new-instance
  2. Heap dump by heaptrc unit of C:\freepascal\laz\lazarus.exe
  3. 3740085 memory blocks allocated : 522969118/532855656
  4. 3740082 memory blocks freed     : 522969046/532855584
  5. 3 unfreed memory blocks : 72
  6. True heap size : 1540096 (256 used in System startup)
  7. True free heap : 1539456
  8. Should be : 1539480
  9. Call trace for block $266AA0D0 size 24
  10.   $00415CF6
  11.   $00411D68
  12.   $0055DC94  CREATE,  line 5364 of lresources.pp
  13.   $00F5BDB2  PARSESOURCES,  line 324 of LazProfilerAddon.pas
  14.   $00F5DE17  PROJECTBUILDING,  line 742 of LazProfilerAddon.pas
  15.   $0080E74D  DOCALLMODALFUNCTIONHANDLER,  line 673 of lazideintf.pas
  16.   $0047299D  DOBUILDPROJECT,  line 6713 of main.pp
  17.   $00474A15  DORUNPROJECTWITHOUTDEBUG,  line 7194 of main.pp
  18.   $00F5E8D9  START,  line 886 of LazProfilerAddon.pas
  19.   $0080A215  MENUITEMCLICK,  line 549 of menuintf.pas
  20.   $0080D475  MENUITEMCLICK,  line 1710 of menuintf.pas
  21.   $005F4624  CLICK,  line 83 of include/menuitem.inc
  22.   $005F4EA5  DOCLICKED,  line 293 of include/menuitem.inc
  23.   $00412275
  24.   $00593DE8  DOWINDOWPROC,  line 2081 of win32/win32callback.inc
  25.   $00595579  WINDOWPROC,  line 2699 of win32/win32callback.inc
  26. Call trace for block $1EA4DA28 size 24
  27.   $00415CF6
  28.   $00411D68
  29.   $0055DC94  CREATE,  line 5364 of lresources.pp
  30.   $00F5BD48  PARSESOURCES,  line 318 of LazProfilerAddon.pas
  31.   $00F5DE17  PROJECTBUILDING,  line 742 of LazProfilerAddon.pas
  32.   $0080E74D  DOCALLMODALFUNCTIONHANDLER,  line 673 of lazideintf.pas
  33.   $0047299D  DOBUILDPROJECT,  line 6713 of main.pp
  34.   $00474A15  DORUNPROJECTWITHOUTDEBUG,  line 7194 of main.pp
  35.   $00F5E8D9  START,  line 886 of LazProfilerAddon.pas
  36.   $0080A215  MENUITEMCLICK,  line 549 of menuintf.pas
  37.   $0080D475  MENUITEMCLICK,  line 1710 of menuintf.pas
  38.   $005F4624  CLICK,  line 83 of include/menuitem.inc
  39.   $005F4EA5  DOCLICKED,  line 293 of include/menuitem.inc
  40.   $00412275
  41.   $00593DE8  DOWINDOWPROC,  line 2081 of win32/win32callback.inc
  42.   $00595579  WINDOWPROC,  line 2699 of win32/win32callback.inc
  43. Call trace for block $1EA4F428 size 24
  44.   $00415CF6
  45.   $00411D68
  46.   $0055DC94  CREATE,  line 5364 of lresources.pp
  47.   $00F5BCDE  PARSESOURCES,  line 312 of LazProfilerAddon.pas
  48.   $00F5DE17  PROJECTBUILDING,  line 742 of LazProfilerAddon.pas
  49.   $0080E74D  DOCALLMODALFUNCTIONHANDLER,  line 673 of lazideintf.pas
  50.   $0047299D  DOBUILDPROJECT,  line 6713 of main.pp
  51.   $00474A15  DORUNPROJECTWITHOUTDEBUG,  line 7194 of main.pp
  52.   $00F5E8D9  START,  line 886 of LazProfilerAddon.pas
  53.   $0080A215  MENUITEMCLICK,  line 549 of menuintf.pas
  54.   $0080D475  MENUITEMCLICK,  line 1710 of menuintf.pas
  55.   $005F4624  CLICK,  line 83 of include/menuitem.inc
  56.   $005F4EA5  DOCLICKED,  line 293 of include/menuitem.inc
  57.   $00412275
  58.   $00593DE8  DOWINDOWPROC,  line 2081 of win32/win32callback.inc
  59.   $00595579  WINDOWPROC,  line 2699 of win32/win32callback.inc
  60.  

So storage shouldn't be a problem here.

Which influence has the type of debuginformation?
laz trunk - fpc trunk 32bit - Windows 10 Pro x64 (1803)

440bx

  • Sr. Member
  • ****
  • Posts: 391
Re: Why does it takes so long to build the heaptrace log for unfreed blocks
« Reply #3 on: September 22, 2018, 09:05:58 am »
If i end Lazarus with for example 3 unfreed blocks it takes more than 30 s for the following output:
Have you looked at the CPU usage in your machine during those 30 seconds ?  I suspect that during those 30 seconds there is one core at 100%.  If you have 8 cores, that means that one core will be at 12.5% and the system slightly above that depending on what else your machine is busy doing.

I haven't looked at the code that tracks and reconciles heap usage but, even without doing that, it's very likely that the code is single threaded.  In addition to that, you can see that the number of blocks that have been allocated and freed is a fair number, IOW, there is a fair amount of work to match and reconcile allocations and releases.  In addition to that, the system also has to assemble the call sequence that lead to the unallocated blocks, depending on the implementation, that can take some time too.

Leledumbo is right, whenever you need to figure out why a program or routine is taking more time than you like/expect, it's time to use a profiler.  That's the only safe way of determining the reason for the time spent.

My smell guess is that the time reflects mostly the fact that the reconciliation is single threaded and the fairly large number of memory blocks there are to track.  A profiler is the right way of figuring out the exact reason and the details related to it.

HTH.



Pascal

  • Hero Member
  • *****
  • Posts: 783
Re: Why does it takes so long to build the heaptrace log for unfreed blocks
« Reply #4 on: September 22, 2018, 09:57:55 am »
Yes, you are right. It's a single thread doing the work.
But it only steps through a list of 3 blocks, which remain unfreed, and calls call_stack for each block.
I tried to put in some extra debug info but i can't use SysUtils in heaptrc.pp, so no time stamps.
laz trunk - fpc trunk 32bit - Windows 10 Pro x64 (1803)

Pascal

  • Hero Member
  • *****
  • Posts: 783
Re: Why does it takes so long to build the heaptrace log for unfreed blocks
« Reply #5 on: September 24, 2018, 08:30:33 am »
Maybe this is related to the version of gdb i am using (8.0.1).

call_stack() calls BackTraceStrFunc() for every address which in fact is GdbBackTraceStr() which
calls gdb to query the line info. Maybe this takes so long with dgb 8.0.1.

Does anyone know where to find a gdb 8.2 win64 executable?
laz trunk - fpc trunk 32bit - Windows 10 Pro x64 (1803)

Thaddy

  • Hero Member
  • *****
  • Posts: 7195
Re: Why does it takes so long to build the heaptrace log for unfreed blocks
« Reply #6 on: September 24, 2018, 09:05:50 am »
No. afaik mingw is still on 7 and cygwin64 has 8.0.1.
You have to build it yourself.

That said: I think that is not the issue.
I think, but have to check, that the depth is not 3 but configurable. If I look at my configuration  it does 5.
inline variables like in D10.3 are a bit like Brexit: if you are given the wrong information it sounds like a good idea. Every kid loves candy, but it makes you fat and your teeth will disappear.

Pascal

  • Hero Member
  • *****
  • Posts: 783
Re: Why does it takes so long to build the heaptrace log for unfreed blocks
« Reply #7 on: September 24, 2018, 09:49:28 am »
Just enabled DEBUG_LINEINFO.

StabBackTraceStr of rtl\inc\lineinfo.pp is used. So no gdb issue.

Code: Text  [Select]
  1. ...
  2. StabBackTraceStr called
  3. GetLineInfo called
  4. C:\freepascal\laz\lazarus.exe Baseaddr: 00400000
  5. Addr: 00415BE6
  6. ...
laz trunk - fpc trunk 32bit - Windows 10 Pro x64 (1803)