Gotham memory leak on video playback
#31
I tried to play MythBuster episode with SRT subtitle. Only got time to play 30minutes and the free memory dropped about 25MB during play back. The issue is that the free memory does not recover immediately after I stopped playing. Will need to double check tomorrow to see if they are released later. Anyway, this is much more insignificant when compared to ASS format.

Note that I changed the GUI language to English as intrusted. Waste some effort making Chinese subtitle working with it. Not sure what does it mean with the current result. Will try this with ASS later.
Reply
#32
Update: I go back to check the free memory after idling for eight hours and doesn't find any luck. I'm still not very sure if it's a leak or some kind of memory caching. will keep monitoring.
Reply
#33
I played the same episode again, with subtitle character set set to default so that Chinese characters are shown as some garbage symbols. This time the free memory is quite stable for the firt 30 minutes but dropped about 10MB within last 10minutes.
So the free memory goes all the way from 478MB (before experiment in last post) to 450MB (after experiment in last post) and then to 438MB(now).
Still not sure if this is caching or leaking, will repeat the same episode later.
Reply
#34
I repeat the same episode for three more times and then a different episode that also with SRT subtle. There's no further drop on free memory -- it ends up with 435MB. While I have no idea how to explain the 40MB drop in the first trail, this should not be considered as a sign of leak.
Reply
#35
Another experiment with ASS subtitle in English GUI and the leakage is not affected just as expected. One thing to note is that I find XBMC become unresponsive when free memory is shown as 230MB. This is more than the typical value of 150MB or so. This remind me that once I checked the free memory from SSH console, the OS report ed value is different from the XBMC reported one -- it's close to zero when XBMC says about 150MB. I thought that may be a fixed difference but this appear to be not the case. I did not restart XBMC after all experiments mentioned in the above posts. Maybe there are some leakage that is not reflected from XBMC reported free memory?
Does it have anything to do with the integrated GPU that steals main memory?
Reply
#36
I think the above has to do with lack of knowledge on your part about how linux handles memory - What command are you using to see free memory in the OS ?

Just to be clear : we have been unable to reproduce the leaking you thought to see,
Everything we though to see was either file caching of linux, or just a difference in how different linux components calculate free / shared memory.
I am going to need exact steps how to reproduce this to get more people to look at it.

Possibly you could upload the files used somewhere ?
Publish exact steps as well as commands you use to reproduce.
If you have any relevant logs from a crash (syslog, dmesg etc) please pastebin them as well.
Reply
#37
The real memory consumption has to be monitored via "top" and the vsize value of the XBMC process only. Anything else is incorrect and leads to wrong assumptions. Best thing to do is run XBMC via valgrind - but that tool is only good for advanced users/developers which are used to work with it.
AppleTV4/iPhone/iPod/iPad: HowTo find debug logs and everything else which the devs like so much: click here
HowTo setup NFS for Kodi: NFS (wiki)
HowTo configure avahi (zeroconf): Avahi_Zeroconf (wiki)
READ THE IOS FAQ!: iOS FAQ (wiki)
Reply
#38
It's really surprising that this cannot be reproduced.
Since this always happens from my side, I'm not sure what's the key factor to reproduce...
I may be able to upload the subtitle file somewhere for you to try.

As of the memory issue, I checked the output from both 'free' command and the top.
I didn't aware of the missing cached column from the free output.
Really strange, must be specific to Openelec -- my Debian version of free has the cache column.
From /proc/meminfo, I can see that there are about 100MB cache. So you are right, the XBMC report should be precise.
Finally I also quote the output from TOP, showing that XBMC is using most of the memory.
But again the output format is also strange, doesn't carry breakdown like VIRT / RES / SHR...
As of syslog, I also really wish I can have one, but openelec doesn't seem to provide...

Code:
OpenELEC:~ # free
             total         used         free       shared      buffers
Mem:        733252       707296        25956            0        17468
-/+ buffers:             689828        43424
Swap:            0            0            0


OpenELEC:~ # cat /proc/meminfo
MemTotal:         733252 kB
MemFree:           25980 kB
MemAvailable:      60176 kB
Buffers:           17468 kB
Cached:           108840 kB
SwapCached:            0 kB
Active:           576648 kB
Inactive:          95496 kB
Active(anon):     546580 kB
Inactive(anon):    53848 kB
Active(file):      30068 kB
Inactive(file):    41648 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:             0 kB
SwapFree:              0 kB
Dirty:                 0 kB
Writeback:             0 kB
AnonPages:        545904 kB
Mapped:            22468 kB
Shmem:             54592 kB
Slab:              18948 kB
SReclaimable:       6844 kB
SUnreclaim:        12104 kB
KernelStack:         904 kB
PageTables:         2396 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:      366624 kB
Committed_AS:     827072 kB
VmallocTotal:   34359738367 kB
VmallocUsed:      282084 kB
VmallocChunk:   34359452015 kB
AnonHugePages:         0 kB
DirectMap4k:       12288 kB
DirectMap2M:      765952 kB


Mem: 707920K used, 25332K free, 0K shrd, 140081109471360K buff, 24227544K cache
CPU:  0.5% usr  0.2% sys  0.0% nic 98.0% idle  0.7% io  0.0% irq  0.0% sirq
Load average: 0.00 0.02 0.05 1/107 15402
  PID  PPID USER     STAT   VSZ %VSZ CPU %CPU COMMAND
13864     1 root     S    1791m249.1   1  0.6 /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13875     1 root     S N  1791m249.1   1  0.2 {PeripBusCEC} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13876     1 root     S N  1791m249.1   0  0.1 {PeripBusUSBUdev} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13889     1 root     S    1791m249.1   1  0.1 /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
  425   417 root     S    63352  8.6   1  0.1 /usr/bin/Xorg vt01 -logverbose 6 -verbose 6 -s 0 -noreset -allowMouseOpenFail
13880     1 root     S    1791m249.1   0  0.0 {LanguageInvoker} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13873     1 root     S    1791m249.1   1  0.0 {ActiveAE} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13874     1 root     S <  1791m249.1   0  0.0 {AESink} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13890     1 root     S    1791m249.1   1  0.0 {AirPlayServer} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13886     1 root     S    1791m249.1   1  0.0 {EventServer} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13887     1 root     S    1791m249.1   1  0.0 {TCPServer} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13885     1 root     S    1791m249.1   0  0.0 {libmicrohttpd} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13882     1 root     S    1791m249.1   1  0.0 /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13910     1 root     S    1791m249.1   1  0.0 {LanguageInvoker} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13884     1 root     S    1791m249.1   0  0.0 {libmicrohttpd} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
13911     1 root     S    1791m249.1   1  0.0 {LanguageInvoker} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
15278     1 root     S    1791m249.1   1  0.0 {libmicrohttpd} /usr/lib/xbmc/xbmc.bin --standalone -fs --lircdev /run/lirc/lircd --debug
  461   417 root     S    63352  8.6   1  0.0 /usr/bin/Xorg vt01 -logverbose 6 -verbose 6 -s 0 -noreset -allowMouseOpenFail
15394   354 root     S    26060  3.5   0  0.0 sshd: root@pts/0

I've upload the subtitle that is leaking here to this location.
http://www.filedropper.com/mythbusterss0...x264-dhdzh

I think you can force load this one with any video -- hope this would reproduce the leak if the subtitle is really the offender.
Reply
#39
Actually I can be a power user even though I really don't want to do it by myself in this case since openelec is really not a good debug environment.
But since the developer has no luck on reproducing, I have to give it a kick otherwise the thread may sink silently.

An valgrind log from an idle XBMC: http://www.filedropper.com/xbmcidle
An valgrind log from XBMC playing back with the ASS subtitle I attached above: http://www.filedropper.com/xbmcass

To get these logs I have to rebuild the openelec image with non-stripped binary and add the valgrind tool.
I only rebuild three of the component with non-stripped -- eglibc6, xbmc && libass.

Here are an example of leakage log.
Not sure if this is enough for develops to identify the leak.
Really have no idea what the inner stacks are referring to.
Isn't it libass?

==1286== 65,460,853 bytes in 1,412 blocks are possibly lost in loss record 4,308 of 4,308
==1286== at 0x4C29DA4: malloc (vg_replace_malloc.c:291)
==1286== by 0x7A19BCE: Huh
==1286== by 0x7A0FDFD: Huh
==1286== by 0x7A0FE46: Huh
==1286== by 0x7A10674: Huh
==1286== by 0x7A0AA12: Huh
==1286== by 0x7A1A1BD: Huh
==1286== by 0x89599A: CDVDSubtitlesLibass::RenderImage(int, int, double, int*) (DVDSubtitlesLibass.cpp:169)
==1286== by 0x8FF630: OVERLAY::CRenderer::Convert(CDVDOverlaySSA*, double) (OverlayRenderer.cpp:292)
==1286== by 0x8FF69C: OVERLAY::CRenderer::Convert(CDVDOverlay*, double) (OverlayRenderer.cpp:314)
==1286== by 0x9002C2: OVERLAY::CRenderer::Render(int) (OverlayRenderer.cpp:183)
==1286== by 0x8F62D5: CXBMCRenderManager::Render(bool, unsigned int, unsigned int) (RenderManager.cpp:774)
==1286==
==1286== LEAK SUMMARY:
==1286== definitely lost: 220,645 bytes in 1,258 blocks
==1286== indirectly lost: 763,353 bytes in 4,753 blocks
==1286== possibly lost: 245,662,210 bytes in 33,291 blocks
==1286== still reachable: 31,817,553 bytes in 99,624 blocks
==1286== suppressed: 0 bytes in 0 blocks
Reply
#40
I think I figured out the root cause. Good news to XBMC guys -- this is libass's fault.
But I think the valgrind log still indicates some other minor leak inside XBMC.

Back to the issue:
It's an issue introduced in libass v 0.11.0 (https://github.com/libass/libass/releases/tag/0.11.0)
The exact offending CL is 5dd56af, which effectively changed the cache size from about 30MB to 1GB.

Code:
In ass_render.h
45           -#define GLYPH_CACHE_MAX 1000
46           -#define BITMAP_CACHE_MAX_SIZE 30 * 1048576
      46     +#define GLYPH_CACHE_MAX 10000
      47     +#define BITMAP_CACHE_MAX_SIZE 500 * 1048576
      48     +#define COMPOSITE_CACHE_MAX_SIZE 500 * 1048576
So technically this is not a leak since the memory is still tracked, but it simply won't be released.
BTW, this so called cache really sucks. There is no replacement upon cache full, but a full invalidation instead.
So when the cache grows all the way to 500MB, it drops everything and do it all over again.


BTW, here are the full memory leak stack if anybody interests.
Memory allocated from these code path are placed into the cache mentioned above.
Code:
==1469== 2,258,656 (+656,795) bytes in 510 (+135) blocks are possibly lost in loss record 37,970 of 37,988
==1469==    at 0x4C29DA4: malloc (vg_replace_malloc.c:291)
==1469==    by 0x7AF9BCE: ass_aligned_alloc (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AEFDFD: alloc_bitmap (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AF04D2: outline_to_bitmap (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AE9BE9: ass_render_event.lto_priv.84 (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AFA1BD: ass_render_frame (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x89599A: CDVDSubtitlesLibass::RenderImage(int, int, double, int*) (DVDSubtitlesLibass.cpp:169)
==1469==    by 0x8FF630: OVERLAY::CRenderer::Convert(CDVDOverlaySSA*, double) (OverlayRenderer.cpp:292)
==1469==    by 0x8FF69C: OVERLAY::CRenderer::Convert(CDVDOverlay*, double) (OverlayRenderer.cpp:314)
==1469==    by 0x9002C2: OVERLAY::CRenderer::Render(int) (OverlayRenderer.cpp:183)
==1469==    by 0x8F62D5: CXBMCRenderManager::Render(bool, unsigned int, unsigned int) (RenderManager.cpp:774)
==1469==    by 0xA56D61: CApplication::RenderNoPresent() (Application.cpp:2168)
==1469==
==1469== 2,365,746 (+792,346) bytes in 62 (+22) blocks are possibly lost in loss record 37,971 of 37,988
==1469==    at 0x4C29DA4: malloc (vg_replace_malloc.c:291)
==1469==    by 0x7AF9BCE: ass_aligned_alloc (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AEFDFD: alloc_bitmap (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AEA673: ass_render_event.lto_priv.84 (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AFA1BD: ass_render_frame (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x89599A: CDVDSubtitlesLibass::RenderImage(int, int, double, int*) (DVDSubtitlesLibass.cpp:169)
==1469==    by 0x8FF630: OVERLAY::CRenderer::Convert(CDVDOverlaySSA*, double) (OverlayRenderer.cpp:292)
==1469==    by 0x8FF69C: OVERLAY::CRenderer::Convert(CDVDOverlay*, double) (OverlayRenderer.cpp:314)
==1469==    by 0x9002C2: OVERLAY::CRenderer::Render(int) (OverlayRenderer.cpp:183)
==1469==    by 0x8F62D5: CXBMCRenderManager::Render(bool, unsigned int, unsigned int) (RenderManager.cpp:774)
==1469==    by 0xA56D61: CApplication::RenderNoPresent() (Application.cpp:2168)
==1469==    by 0xA5601A: CApplication::Render() (Application.cpp:2284)
==1469==
==1469== 2,367,648 (+794,248) bytes in 64 (+24) blocks are possibly lost in loss record 37,972 of 37,988
==1469==    at 0x4C29DA4: malloc (vg_replace_malloc.c:291)
==1469==    by 0x7AF9BCE: ass_aligned_alloc (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AEFDFD: alloc_bitmap (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AEFE46: copy_bitmap (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AF0674: make_shadow_bitmap.lto_priv.90 (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AEAA12: ass_render_event.lto_priv.84 (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x7AFA1BD: ass_render_frame (in /usr/lib/libass.so.5.0.0)
==1469==    by 0x89599A: CDVDSubtitlesLibass::RenderImage(int, int, double, int*) (DVDSubtitlesLibass.cpp:169)
==1469==    by 0x8FF630: OVERLAY::CRenderer::Convert(CDVDOverlaySSA*, double) (OverlayRenderer.cpp:292)
==1469==    by 0x8FF69C: OVERLAY::CRenderer::Convert(CDVDOverlay*, double) (OverlayRenderer.cpp:314)
==1469==    by 0x9002C2: OVERLAY::CRenderer::Render(int) (OverlayRenderer.cpp:183)
==1469==    by 0x8F62D5: CXBMCRenderManager::Render(bool, unsigned int, unsigned int) (RenderManager.cpp:774)
Reply
#41
I'm now able to watch episodes with ASS subtitles for 2+ hours after limiting the libass cache size down to 60MB.
There are two episodes in total and the free memory drops from about 530MB to about 470MB and finally to 450MB.
As a comparison, the free memory used to drop all the way to 150MB within 40~80 mins.

I still suspect there are some more minor leak behind the gradual drop of memory after each episode.
But that will be a different story.

PS: I don't have an github account, can anybody help raising an issue to libass upstream for me, referring to this thread?
Thanks in advance.
Reply
#42
Thx for your hard work on tracking it down. I have pinged the dev who was in charge for the version bump in our tree...
AppleTV4/iPhone/iPod/iPad: HowTo find debug logs and everything else which the devs like so much: click here
HowTo setup NFS for Kodi: NFS (wiki)
HowTo configure avahi (zeroconf): Avahi_Zeroconf (wiki)
READ THE IOS FAQ!: iOS FAQ (wiki)
Reply
#43
Turns out this is a known issue at upstream, so just waiting for a new release with fix. Make sure sticking to version prior to 0.11.0 for now.

Currently I keep watching more MythBuster episodes and monitoring the free memory.
After about 6~7 more episodes (~40Mins each), the free memory dropped to about 200MB.
Will keep going and see if this will drive the XBMC to OOM crash.

PS: I searched for libass memory leakage on the network and find an ancient xbmc ticket: http://trac.xbmc.org/ticket/10896
The syndrome looks quite similar about inter-episode memory loss, but this should have been fixed 4 years ago and should not be the same issue.
Reply
#44
Well, my XBMC died with about 3~4 more episodes.
So the libass cache size issue is not the ultimate root cause. There must be some leakage somewhere within XBMC.
I think the valgrind log in post #39 do serve as a proof.
It just come to my mind that I did clean shutdown of XBMC on that valgrind run (stopped the playback first and quite XBMC through xbmc-send).
From LIBASS POV, that memory is in cache not leak.
If that's shown up in the leak report after a clean XBMC shutdown, it should serve as a proof that XBMC does not do proper memory release on either playback stopping or program shutdown.

Can any developer revisit the ASS subtitle shutdown / release code to see if there are anything wrong?

From the debug log, I see CDVDSubtitlesLibass initialization for each episodes but there is no counterpart for shutdown.
Since we really don't have shutdown log in the code so we have no idea if we are doing proper shutdown at all.
Somebody need to do some debugging.
Reply

Logout Mark Read Team Forum Stats Members Help
Gotham memory leak on video playback2