Why does it takes so long to build the heaptrace log for unfreed
blocks
lazarus / 62-General

----------------------------------------------------------------------
Pascal · 2018-09-20 07:09

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?

----------------------------------------------------------------------
Leledumbo · 2018-09-21 20:50

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 · 2018-09-22 04:24

Output is redirected to file on SSD:
Code: Pascal  [Select][+][-]window.onload = function(){var x1 =
document.getElementById("main_content_section"); if (x1) { var x =
document.getElementsByClassName("geshi");for (var i = 0; i program
Lazarus;...begin  {$If Declared(UseHeapTrace)}  DeleteFile('lazarus-
heaptrace.log');  SetHeapTraceOutput('lazarus-heaptrace.log');  //
don't show empty heaptrc output  GlobalSkipIfNoLeaks := True; 
{$endif} 
If i end Lazarus with for example 3 unfreed blocks it takes more than
30 s for the following output:
Code: Text  [Select][+][-]window.onload = function(){var x1 =
document.getElementById("main_content_section"); if (x1) { var x =
document.getElementsByClassName("geshi");for (var i = 0; i
C:\freepascal\laz\lazarus.exe --no-splash-screen --started-by-
startlazarus --primary-config-path=C:\freepascal\Config\i386 --force-
new-instance Heap dump by heaptrc unit of
C:\freepascal\laz\lazarus.exe3740085 memory blocks allocated :
522969118/5328556563740082 memory blocks freed     :
522969046/5328555843 unfreed memory blocks : 72True heap size :
1540096 (256 used in System startup)True free heap : 1539456Should be
: 1539480Call trace for block $266AA0D0 size 24  $00415CF6  $00411D68 
$0055DC94  CREATE,  line 5364 of lresources.pp  $00F5BDB2
 PARSESOURCES,  line 324 of LazProfilerAddon.pas  $00F5DE17
 PROJECTBUILDING,  line 742 of LazProfilerAddon.pas  $0080E74D
 DOCALLMODALFUNCTIONHANDLER,  line 673 of lazideintf.pas  $0047299D
 DOBUILDPROJECT,  line 6713 of main.pp  $00474A15
 DORUNPROJECTWITHOUTDEBUG,  line 7194 of main.pp  $00F5E8D9  START,
 line 886 of LazProfilerAddon.pas  $0080A215  MENUITEMCLICK,  line 549
of menuintf.pas  $0080D475  MENUITEMCLICK,  line 1710 of menuintf.pas 
$005F4624  CLICK,  line 83 of include/menuitem.inc  $005F4EA5
 DOCLICKED,  line 293 of include/menuitem.inc  $00412275  $00593DE8
 DOWINDOWPROC,  line 2081 of win32/win32callback.inc  $00595579
 WINDOWPROC,  line 2699 of win32/win32callback.incCall trace for block
$1EA4DA28 size 24  $00415CF6  $00411D68  $0055DC94  CREATE,  line 5364
of lresources.pp  $00F5BD48  PARSESOURCES,  line 318 of
LazProfilerAddon.pas  $00F5DE17  PROJECTBUILDING,  line 742 of
LazProfilerAddon.pas  $0080E74D  DOCALLMODALFUNCTIONHANDLER,  line 673
of lazideintf.pas  $0047299D  DOBUILDPROJECT,  line 6713 of main.pp 
$00474A15  DORUNPROJECTWITHOUTDEBUG,  line 7194 of main.pp  $00F5E8D9
 START,  line 886 of LazProfilerAddon.pas  $0080A215  MENUITEMCLICK,
 line 549 of menuintf.pas  $0080D475  MENUITEMCLICK,  line 1710 of
menuintf.pas  $005F4624  CLICK,  line 83 of include/menuitem.inc 
$005F4EA5  DOCLICKED,  line 293 of include/menuitem.inc  $00412275 
$00593DE8  DOWINDOWPROC,  line 2081 of win32/win32callback.inc 
$00595579  WINDOWPROC,  line 2699 of win32/win32callback.incCall trace
for block $1EA4F428 size 24  $00415CF6  $00411D68  $0055DC94  CREATE,
 line 5364 of lresources.pp  $00F5BCDE  PARSESOURCES,  line 312 of
LazProfilerAddon.pas  $00F5DE17  PROJECTBUILDING,  line 742 of
LazProfilerAddon.pas  $0080E74D  DOCALLMODALFUNCTIONHANDLER,  line 673
of lazideintf.pas  $0047299D  DOBUILDPROJECT,  line 6713 of main.pp 
$00474A15  DORUNPROJECTWITHOUTDEBUG,  line 7194 of main.pp  $00F5E8D9
 START,  line 886 of LazProfilerAddon.pas  $0080A215  MENUITEMCLICK,
 line 549 of menuintf.pas  $0080D475  MENUITEMCLICK,  line 1710 of
menuintf.pas  $005F4624  CLICK,  line 83 of include/menuitem.inc 
$005F4EA5  DOCLICKED,  line 293 of include/menuitem.inc  $00412275 
$00593DE8  DOWINDOWPROC,  line 2081 of win32/win32callback.inc 
$00595579  WINDOWPROC,  line 2699 of win32/win32callback.inc 
So storage shouldn't be a problem here.

Which influence has the type of debuginformation?

----------------------------------------------------------------------
440bx · 2018-09-22 07:05

Quote from: Pascal on September 22, 2018, 06:24:03 amIf 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 · 2018-09-22 07:57

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.

----------------------------------------------------------------------
Pascal · 2018-09-24 06:30

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?

----------------------------------------------------------------------
Thaddy · 2018-09-24 07:05

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.

----------------------------------------------------------------------
Pascal · 2018-09-24 07:49

Just enabled DEBUG_LINEINFO.

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

Code: Text  [Select][+][-]window.onload = function(){var x1 =
document.getElementById("main_content_section"); if (x1) { var x =
document.getElementsByClassName("geshi");for (var i = 0; i
...StabBackTraceStr calledGetLineInfo
calledC:\freepascal\laz\lazarus.exe Baseaddr: 00400000Addr:
00415BE6...