Tracking a memory leak

[Volker Dobler]

I have been trying to track a memory leak in my Go program,
but got stuck and am unsure how to interpret the pprof and
ReadMemStats results. Any help is appreciated!

After approx 3000 iterations of the main loop the program
terminates with "throw: out of memory (FixAlloc)".

Memory consumption [1] as reported by runtime.ReadMemStats
show a steady increase of TotalAlloc while all other readings
stay pretty much flat (HeapOpbject vary due to different stuff
done during the running time).

A memory profiles created during the running time
seems normal to me:

$ ~/go/misc/pprof migrator prof.00001500.mprof
Adjusting heap profiles for 1-in-64 sampling rate
Welcome to pprof! For help, type 'help'.
(pprof) top
Total: 1.8 MB
0.4 23.9% 23.9% 0.4 23.9% migration.NewNode
0.3 13.8% 37.8% 0.3 13.8% migration.splitSitemap
0.2 13.0% 50.7% 0.3 16.4% io/ioutil.readAll
0.2 13.0% 63.7% 1.0 54.9%
migration.I18nKeyMappingFromFile
0.1 7.6% 71.3% 0.6 34.6% migration.parse
0.1 5.1% 76.4% 0.1 5.1% migration.(*Job).addPage
0.1 4.0% 80.5% 0.1 4.3% os.NewFile
0.1 3.5% 84.0% 0.1 3.5% bytes.makeSlice
0.1 2.9% 87.0% 0.1 2.9% encoding/xml.(*Decoder).name
0.1 2.8% 89.8% 0.1 3.3% migration.parseRule
(pprof) top --cum
Total: 1.8 MB
0.0 0.0% 0.0% 1.8 99.9% schedunlock
0.0 0.0% 0.0% 1.6 86.5% main.main
0.0 0.0% 0.0% 1.6 86.5% runtime.main
0.0 0.0% 0.0% 1.6 86.5% main.runCmdlineInterface
0.0 0.0% 0.0% 1.0 54.9% main.readTranslationMapping
0.2 13.0% 13.0% 1.0 54.9%
migration.I18nKeyMappingFromFile
0.0 0.0% 13.0% 0.6 34.7% migration.ParseXml
0.1 7.6% 20.6% 0.6 34.6% migration.parse
0.0 0.0% 20.6% 0.6 31.4% main.performExport
0.0 0.0% 20.6% 0.4 24.2% migration.NewJob
(pprof)


Comparing a "late" memory profile against an "early" baseline:
$ ~/go/misc/pprof --base prof.00000100.mprof migrator prof.
00001500.mprof
Adjusting heap profiles for 1-in-64 sampling rate
Adjusting heap profiles for 1-in-64 sampling rate
Welcome to pprof! For help, type 'help'.
(pprof) top
Total: 0.2 MB
0.1 37.3% 37.3% 0.1 37.5% os.NewFile
0.1 27.2% 64.5% 0.1 44.5% migration.parse
0.0 15.5% 80.0% 0.0 15.5% migration.NewRootNode
0.0 14.9% 94.9% 0.0 14.9% migration.NewNode
0.0 2.6% 97.6% 0.0 2.6% migration.AddMissingType
0.0 2.1% 99.7% 0.0 2.1% migration.AttributeRule.Apply
0.0 1.7% 101.4% 0.0 1.7% encoding/xml.(*Decoder).name
0.0 1.1% 102.5% 0.0 15.7% migration.SourceInfo.FetchPage
0.0 0.5% 102.9% 0.0 0.5% runtime.appendstr
0.0 0.3% 103.2% 0.0 0.4% runtime.newm
(pprof) top --cum
Total: 0.2 MB
0.0 0.0% 0.0% 0.2 100.9% migration.
(*MigrationRun).migrateSinglePage
0.0 0.0% 0.0% 0.2 100.7% migration.ExportPage
0.0 0.0% 0.0% 0.2 99.6% schedunlock
0.0 0.0% 0.0% 0.1 45.0% migration.ParseXml
0.0 0.0% 0.0% 0.1 45.0% migration.PrepareXML
0.1 27.2% 27.2% 0.1 44.5% migration.parse
0.1 37.3% 64.5% 0.1 37.5% os.NewFile
0.0 0.0% 64.5% 0.0 22.2% migration.Page.Save
0.0 0.0% 64.5% 0.0 19.2% os.OpenFile
0.0 0.0% 64.5% 0.0 18.3% net.(*netFD).setAddr


What I cannot interpret is the different numbers pprof and
ReadMemStats
yield for the total: Total increases steadily for ReadMemStats while
it is constant for pprof?
Why do I get an out of memory when only 120 MByte are allocated on
a 4 GB machine?

Any comments of what to check/test else?
(Increasing the accuracy of the allocation counting by reducing
runtime.MemProfileRate to one did not show substantial differences.
Results are the same on Windows and Linux.)

Regards,

Volker


[1] http://imgur.com/IGEot

[Rémy Oudompheng]

On 2012/5/8 Volker Dobler <dr.volke...@gmail.com> wrote:
> I have been trying to track a memory leak in my Go program,
> but got stuck and am unsure how to interpret the pprof and
> ReadMemStats results.  Any help is appreciated!
>
> After approx 3000 iterations of the main loop the program
> terminates with "throw: out of memory (FixAlloc)".

It's rather a bug in the allocator than a memory leak. Are you in 32-bit mode ?

Rémy.

[⚛]

MemStats.TotalAlloc never decreases.

If you run "/usr/bin/time migrator" what do the last two lines look like?

[Volker Dobler]

On May 8, 5:56 pm, ⚛ <0xe2.0x9a.0...@gmail.com> wrote:
> If you run "/usr/bin/time migrator" what do the last two lines look like?

0.00user 0.01system 1:06.94elapsed 0%CPU (0avgtext+0avgdata
201984maxresident)k
0inputs+0outputs (819major+0minor)pagefaults 0swaps

(Under cygwin on Windows, won't have access to Linux for several
hours.)

V.