VMem usage

micantox · 2009-05-08 16:22

Hi all,

I'm opening this thread about memory usage because I've noticed
an abnormal held vmem growth rate. I wanted to share a couple of
thoughts with some more experienced developers.

I'll start from what I figured out by looking at some guilib related
code. It seems to me that xbmc gives the possibility to dynamically
allocate and deallocate gui-related resources, like windows, buttons,
textboxes, or, in contrast, to load and keep them in memory to avoid
further disk activities.

The observed behaviour is that if you click on a menu item (say the
Videos menu one) the vmem grows since the program has to load
all the needed resources. If you get back on the main menu, this
vmem amount does not decrease: to me this would mean that these
resources are kept in memory.

I thought this behaviour depended on m_dynamicResourceAlloc and
m_loadOnDemand bools, but I found both of them set to a dynamic
alloc/dealloc pair for every gui element. In my understanding this
should have meant everything being continuously allocated and
deallocated.

If I am not completely wrong, then how can this be explained?

Thanks in advance,
M.

**jmarshall** · 2009-05-09 01:04

Are you certain it is not an artifact of the OS keeping the memory around in case it is requested again?

Cheers,
Jonathan

micantox · 2009-05-11 09:46

jmarshall Wrote:Are you certain it is not an artifact of the OS keeping the memory around in case it is requested again?

Cheers,
Jonathan

Thanks for your answer. I guess you are right: I noticed that, despite of the vmem increase, the real memory allocated to the process changes back and forth. I must investigate more on this. Sorry for the noise.

Cheers.

micantox · 2009-05-26 14:31

Sorry if I take again this discussion to your attention, but I had some more details about this.

Please note that all of this has been obtained by simply alternating a start and a stop (enter - esc) command on a movie file in the Videos menu of the standard skin. If you open a top you will see the virt column continuously grow.

In my last session, this is the output of top related to xbmc.bin:

Code:

PID    USER    PR    NI    VIRT    RES    SHR    S    %CPU     %MEM    TIME+     COMMAND 

20955  xbmc    20    0     2915m    568m  29m    T    0        37.7    24:18.30    xbmc.bin

in correspondence of a crash. A backtrace informed me that the crash happened when XBMC was trying to create an SDL surface with the following row:

Code:

*ppTexture = SDL_CreateRGBSurface(SDL_HWSURFACE, width, height, 32, RMASK, GMASK, BMASK, AMASK);

which returned a NULL ppTexture, so that the following row,

Code:

if (SDL_LockSurface(*ppTexture) == 0)

segfaulted. The only reason for the CreateRGBSurface to fail was a malloc failure. I used a simple test program which at every iteration tries to allocate an always increasing chunk of memory, freeing it upon success, and it reaches the malloc limit when it tries to allocate more or less the same amount of memory shown in the top line (actually slightly less - 2815 m).

The complete backtrace was the following:

Code:

#0  0xb7cdf81a in SDL_LockSurface () from /usr/lib/libSDL-1.2.so.0

#1  0x0820b056 in GetTextureFromData (pTex=0xa7b14928, texData=0xbda26088, ppTexture=0xbf9a17cc) at DirectXGraphics.cpp:411

#2  0x082a8e4d in CTextureBundle::LoadTexture (this=0x8bf90b4, Filename=@0x1b3b1ef0, pInfo=0xbf9a173c, ppTexture=0xbf9a17cc, ppPalette=0xbf9a17c8) at TextureBundle.cpp:369

#3  0x082ad5b3 in CGUITextureManager::Load (this=0x8bf9080, strTextureName=@0x1b3b1ef0, checkBundleOnly=false) at TextureManager.cpp:515

#4  0x0828ab98 in CGUITextureBase::AllocResources (this=0x1b3b1e70) at GUITexture.cpp:291

#5  0x08245c8a in CGUIControlGroup::Render (this=0x19e92e38) at GUIControlGroup.cpp:107

#6  0x0822e908 in CGUIControl::DoRender (this=0x19e92e38, currentTime=1399104) at GUIControl.cpp:138

#7  0x08245c6d in CGUIControlGroup::Render (this=0x19e53c28) at GUIControlGroup.cpp:111

#8  0x0822e908 in CGUIControl::DoRender (this=0x19e53c28, currentTime=1399104) at GUIControl.cpp:138

#9  0x08292ba0 in CGUIWindow::Render (this=0xb43672c0) at GUIWindow.cpp:338

#10 0x082e6b4c in CApplication::DoRender (this=0x8bfa320) at Application.cpp:2283

#11 0x0854efe4 in CApplicationRenderer::Render (this=0x8bfbe40, bFullscreen=false) at ApplicationRenderer.cpp:312

#12 0x082da7dd in CApplication::RenderNoPresent (this=0x8bfa320) at Application.cpp:2261

#13 0x082daa1e in CApplication::Render (this=0x8bfa320) at Application.cpp:2479

#14 0x0854054b in CXBApplicationEx::Run (this=0x8bfa320) at XBApplicationEx.cpp:259

#15 0x08540954 in main (argc=3, argv=0xbf9a2544) at xbmc.cpp:129

The log confirms XBMC was trying to create an image

Code:

32:44 T:3047782288 M:651059200   DEBUG: ------------------- GUI_MSG_WINDOW_INIT

32:44 T:3047782288 M:651059200   DEBUG: Weather

32:44 T:3047782288 M:651059200   DEBUG: -------------------

32:44 T:3047782288 M:651059200    INFO: Loading skin file: MyWeather.xml

32:44 T:3047782288 M:650649600   DEBUG: Load MyWeather.xml: 53.67ms

32:44 T:3047782288 M:650649600   DEBUG: LoadFile, loading arrowupnf.png

32:44 T:3047782288 M:650649600   DEBUG: Load ArrowUpNF.png: 0.7ms (bundled)

32:44 T:3047782288 M:650547200   DEBUG: LoadFile, loading arrowupfo.png

32:44 T:3047782288 M:650547200   DEBUG: Load ArrowUpFO.png: 0.6ms (bundled)

32:44 T:3047782288 M:650547200   DEBUG: LoadFile, loading arrowdownnf.png

32:44 T:3047782288 M:650547200   DEBUG: Load ArrowDownNF.png: 0.6ms (bundled)

32:44 T:3047782288 M:650547200   DEBUG: LoadFile, loading arrowdownfo.png

32:44 T:3047782288 M:650547200   DEBUG: Load ArrowDownFO.png: 0.6ms (bundled)

32:44 T:3047782288 M:650547200   DEBUG: Alloc resources: 60.44ms (55.66 ms skin load)

32:44 T:3202010000 M:650547200  NOTICE: Parsing widget thumb:

32:44 T:3202010000 M:650547200  NOTICE: Processing key colorkey

32:44 T:3202010000 M:650547200  NOTICE: Image: thumb

32:44 T:3202010000 M:650547200  NOTICE: Creating image: {u'name': u'thumb', u'visible': u'true', u'height': u'150', u'width': u'150', u'colorkey': u'0xFFFFFFFF', u'y': u'40', u'x': u'80', u'filename': u'ticket_ico.png', 'type': u'image'}

32:44 T:3047782288 M:650547200   DEBUG: LoadFile, loading tvfanartoverlay.png

The vast majority of the times this growth of held memory triggers an application freeze. A few times, I had the just described bug.

Any ideas about how to solve this? As I wrote in the first post, it seems that every parameter is set as to free dynamically allocated memory as soon as possible, so I can't understand why all this happens.

micantox · 2009-05-26 15:02

As a further note, I'd like to make a connection with

http://forum.xbmc.org/showthread.php?tid=51315

A strace session attached to the frozen XBMC shows exactly the same kind of neverending cycles I included in that thread. So, it might very likely be the same problem (vmem allocations).

**jmarshall** · 2009-05-26 23:18

Actually, it'll be creating it with SDL_SWSURFACE, not SDL_HWSURFACE (note the ifdef's).

Do you have any idea how large these allocations are - perhaps it's some other reason for the malloc fail (eg corrupt texture, so trying to allocate way too much memory).

Information on which image is being loaded and what size it's trying to allocate (i.e. dump out width, height, and what image it is) might be useful.

Cheers,
Jonathan

micantox · 2009-05-27 09:22

jmarshall Wrote:Actually, it'll be creating it with SDL_SWSURFACE, not SDL_HWSURFACE (note the ifdef's).

Do you have any idea how large these allocations are - perhaps it's some other reason for the malloc fail (eg corrupt texture, so trying to allocate way too much memory).

Information on which image is being loaded and what size it's trying to allocate (i.e. dump out width, height, and what image it is) might be useful.

You are right, of course, and I'll post here this info as soon as this bug is triggered again.

Please note, though, that I almost always get an application freeze (being actually not totally frozen, but waiting for something that does not happen, I think) instead of that bug.

Does it happen to you as well?

I mean if you try to start and immediately stop repeatedly a movie, do you see the virtual memory size constantly increasing? If you had the patience to repeat this plenty of times, when you get around 3000m you could trigger the same problem (after having done it manually once, I had an automatic script issue the commands).

jmarshall Wrote:Cheers,
Jonathan

Thanks again.
M.

micantox · 2009-05-28 16:00

I have compiled SDL libraries from source with debugging symbols and relinked the XBMC executable with them, in order to be able to enter SDL related parts with GDB.

In more than 10 application freezes obtained since then, the very same thing happened. I'll paste here all info I have, hoping you consider this problem of primary importance: if you think that when suspending to ram and resuming you keep executing the very same program session, this allocation problem might definitely bring xbmc to a freeze.

Usual xbmc.bin top related row:

Code:

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                                           

29860 xbmc      20   0 3027m 141m  35m S    0  9.4  16:34.99 xbmc.bin

So the freeze happened at slightly more than 3000m of allocated virtual memory.

Last xbmc.log rows:

Code:

...

06:31 T:3204058000 M:1109303296 WARNING: CDVDMessageQueue(video)::Get - retrieved last data packet of queue

06:32 T:3204058000 M:1109303296    INFO: CDVDPlayerVideo - Stillframe detected, switching to forced 23.976025 fps

06:34 T:2981813136 M:1109147648   DEBUG: webs: accept request

06:34 T:3047393168 M:1109147648   DEBUG: HttpApi Start command: SendKey  paras: SendKey; 61453

06:34 T:3047393168 M:1109147648   DEBUG: OnKey: 61453 pressed, action is 7

06:34 T:3047393168 M:1109147648   DEBUG: new file set audiostream:0

06:34 T:3047393168 M:1109147648   DEBUG: CPlayerCoreFactory::GetPlayers(/home/xbmc/Videos/Wall-E.mkv)

06:34 T:3047393168 M:1109147648  NOTICE: DVDPlayer: Opening: /home/xbmc/Videos/Wall-E.mkv

06:34 T:3047393168 M:1109147648  NOTICE: CDVDPlayer::CloseFile()

06:34 T:3047393168 M:1109147648   DEBUG: OnFileClosed - File was closed

06:34 T:2869316496 M:1109147648  NOTICE: CDVDPlayer::OnExit()

06:34 T:2869316496 M:1109147648  NOTICE: DVDPlayer: closing audio stream

06:34 T:2869316496 M:1109147648  NOTICE: Closing audio stream

06:34 T:2869316496 M:1109147648  NOTICE: Waiting for audio thread to exit

06:34 T:3047393168 M:1109147648  NOTICE: DVDPlayer: waiting for threads to exit

06:37 T:2981813136 M:1109200896   DEBUG: webs: accept request

GDB reports the existence of 8 threads:

Code:

2924 Thread 0xbefa0b90 (LWP 1979)  0xb7f74430 in __kernel_vsyscall ()

  2923 Thread 0xab064b90 (LWP 1978)  0xb7f74430 in __kernel_vsyscall ()

  2921 Thread 0xbf7a1b90 (LWP 1976)  0xb7f74430 in __kernel_vsyscall ()

  5 Thread 0xb1badb90 (LWP 29996)  0xb7f74430 in __kernel_vsyscall ()

  4 Thread 0xb11ffb90 (LWP 29997)  0xb7f74430 in __kernel_vsyscall ()

  3 Thread 0xb09feb90 (LWP 29998)  0xb7f74430 in __kernel_vsyscall ()

  2 Thread 0xb01fdb90 (LWP 29999)  0xb7f74430 in __kernel_vsyscall ()

* 1 Thread 0xb5a38790 (LWP 29860)  0xb7f74430 in __kernel_vsyscall ()

Thread 1 backtrace:

Code:

#0  0xb7f74430 in __kernel_vsyscall ()

#1  0xb714a0e5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/tls/i686/cmov/libpthread.so.0

#2  0xb734c2ed in pthread_cond_wait () from /lib/tls/i686/cmov/libc.so.6

#3  0xb7cfb148 in SDL_CondWait (cond=0xfffffe00, mutex=0xb2955080) at ./src/thread/pthread/SDL_syscond.c:150

#4  0x08829e0a in WaitForEvent (hHandle=0xb2944c60, dwMilliseconds=1) at XSyncUtils.cpp:207

#5  0x08829edd in WaitForSingleObject (hHandle=0xb2944c60, dwMilliseconds=4294967295) at XSyncUtils.cpp:240

#6  0x0889d0d4 in CThread::WaitForThreadExit (this=0xb12d8d98, dwMilliseconds=4294967295) at Thread.cpp:359

#7  0x0889d383 in CThread::StopThread (this=0xb12d8d98) at Thread.cpp:287

#8  0x085c9cc1 in CDVDPlayer::CloseFile (this=0xb12d8d90) at DVDPlayer.cpp:370

#9  0x085cc1c4 in CDVDPlayer::OpenFile (this=0xb12d8d90, file=@0xb1289338, options=@0xbfd91490) at DVDPlayer.cpp:302

#10 0x082e0438 in CApplication::PlayFile (this=0x8c05400, item=@0xb1289338, bRestart=false) at Application.cpp:4375

#11 0x083cd7fd in PLAYLIST::CPlayListPlayer::Play (this=0x8c04da0, iSong=<value optimized out>, bAutoPlay=false, bPlayPrevious=false) at PlayListPlayer.cpp:242

#12 0x083967e4 in CGUIWindowVideoBase::PlayMovie (this=0xb434d688, item=0xbfd917e0) at GUIWindowVideoBase.cpp:1337

...

Thread 2 backtrace

Code:

#0  0xb7f74430 in __kernel_vsyscall ()

#1  0xb72f87a6 in nanosleep () from /lib/tls/i686/cmov/libc.so.6

#2  0x0882acb5 in Sleep (dwMilliSeconds=2954871064) at XTimeUtils.cpp:60

#3  0x088c4eb7 in DBUSSERVER::CDbusServer::Run (this=0x9c11770) at DbusServer.cpp:298

#4  0x0889d568 in CThread::staticThread (data=0x9c11298) at Thread.cpp:206

#5  0x0882b236 in InternalThreadFunc (data=0x9a3a930) at XThreadUtils.cpp:183

#6  0xb7caa39b in SDL_RunThread (data=0x9bba4c0) at ./src/thread/SDL_thread.c:202

#7  0xb7cfac5d in RunThread (data=0x9bba4c0) at ./src/thread/pthread/SDL_systhread.c:47

#8  0xb71464ff in start_thread () from /lib/tls/i686/cmov/libpthread.so.0

#9  0xb733d49e in clone () from /lib/tls/i686/cmov/libc.so.6

Thread 2921 backtrace:

Code:

#0  0xb7f74430 in __kernel_vsyscall ()

#1  0xb732ceab in write () from /lib/tls/i686/cmov/libc.so.6

#2  0xb7cd3b08 in DSP_PlayAudio (this=0x9d1f2a0) at ./src/audio/dsp/SDL_dspaudio.c:135

#3  0xb7ca25c5 in SDL_RunAudio (audiop=0x9d1f2a0) at ./src/audio/SDL_audio.c:215

#4  0xb7caa39b in SDL_RunThread (data=0x9fdf1a8) at ./src/thread/SDL_thread.c:202

#5  0xb7cfac5d in RunThread (data=0x9fdf1a8) at ./src/thread/pthread/SDL_systhread.c:47

#6  0xb71464ff in start_thread () from /lib/tls/i686/cmov/libpthread.so.0

#7  0xb733d49e in clone () from /lib/tls/i686/cmov/libc.so.6

Thread 2923:

Code:

#0  0xb7f74430 in __kernel_vsyscall ()

#1  0xb714a0e5 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/tls/i686/cmov/libpthread.so.0

#2  0xb734c2ed in pthread_cond_wait () from /lib/tls/i686/cmov/libc.so.6

#3  0xb7cfb148 in SDL_CondWait (cond=0xfffffe00, mutex=0x9d60228) at ./src/thread/pthread/SDL_syscond.c:150

#4  0x08829e0a in WaitForEvent (hHandle=0x99f4c30, dwMilliseconds=1) at XSyncUtils.cpp:207

#5  0x08829edd in WaitForSingleObject (hHandle=0x99f4c30, dwMilliseconds=4294967295) at XSyncUtils.cpp:240

#6  0x0889d0d4 in CThread::WaitForThreadExit (this=0xb12d9248, dwMilliseconds=4294967295) at Thread.cpp:359

#7  0x0889d383 in CThread::StopThread (this=0xb12d9248) at Thread.cpp:287

#8  0x085c301d in CDVDPlayerAudio::CloseStream (this=0xb12d9248, bWaitForBuffers=false) at DVDPlayerAudio.cpp:207

#9  0x085c9d68 in CDVDPlayer::CloseAudioStream (this=0xb12d8d90, bWaitForBuffers=<value optimized out>) at DVDPlayer.cpp:2315

#10 0x085cc929 in CDVDPlayer::OnExit (this=0xb12d8d90) at DVDPlayer.cpp:1486

Thread 2924:

Code:

#0  0xb7f74430 in __kernel_vsyscall ()

#1  0xb714a412 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/tls/i686/cmov/libpthread.so.0

#2  0xb734c344 in pthread_cond_timedwait () from /lib/tls/i686/cmov/libc.so.6

#3  0xb7cfb214 in SDL_CondWaitTimeout (cond=0xb12bf060, mutex=0xb12d3ee0, ms=<value optimized out>) at ./src/thread/pthread/SDL_syscond.c:119

#4  0x08829df3 in WaitForEvent (hHandle=0xb2905cb0, dwMilliseconds=100777) at XSyncUtils.cpp:210

#5  0x08829edd in WaitForSingleObject (hHandle=0xb2905cb0, dwMilliseconds=10) at XSyncUtils.cpp:240

#6  0x085bfbff in CDVDMessageQueue::Get (this=0xb12d90ec, pMsg=0xbef9f134, iTimeoutInMilliSeconds=10, priority=0) at DVDMessageQueue.cpp:253

#7  0x085d4621 in CDVDPlayerVideo::Process (this=0xb12d90bc) at DVDPlayerVideo.cpp:287

#8  0x0889d568 in CThread::staticThread (data=0xb12d90bc) at Thread.cpp:206

#9  0x0882b236 in InternalThreadFunc (data=0x9aa8af8) at XThreadUtils.cpp:183

#10 0xb7caa39b in SDL_RunThread (data=0x9c076d8) at ./src/thread/SDL_thread.c:202

#11 0xb7cfac5d in RunThread (data=0x9c076d8) at ./src/thread/pthread/SDL_systhread.c:47

#12 0xb71464ff in start_thread () from /lib/tls/i686/cmov/libpthread.so.0

#13 0xb733d49e in clone () from /lib/tls/i686/cmov/libc.so.6

I think the other ones are not relevant to this problem (web server, event processing). I have no clues about how to proceed now, but it would be an important further step to determine whether this is just a problem of mine or not. I'm more or less SVN-aligned (revision 20666).

micantox · 2009-05-29 17:24

Last XBMC Live is affected by the very same bug (here it led to an application crash). Do you think it's time to open a trac ticket with all the information collected so far?

stubk · 2009-07-18 19:24

micantox Wrote:I have no clues about how to proceed now, but it would be an important further step to determine whether this is just a problem of mine or not. I'm more or less SVN-aligned (revision 20666).

I can confirm that it's not just you with this problem - I have it too at around 2700m virtual memory (aspire revo 1gb, with svn 21749).

I've added details to your trac ticket

micantox Junior Member Posts: 30 Joined: Apr 2009 Reputation: 0	2009-05-11 09:46 Post: #3 jmarshall Wrote:Are you certain it is not an artifact of the OS keeping the memory around in case it is requested again? Cheers, Jonathan Thanks for your answer. I guess you are right: I noticed that, despite of the vmem increase, the real memory allocated to the process changes back and forth. I must investigate more on this. Sorry for the noise. Cheers.
	find quote

micantox Junior Member Posts: 30 Joined: Apr 2009 Reputation: 0	2009-05-26 15:02 Post: #5 As a further note, I'd like to make a connection with http://forum.xbmc.org/showthread.php?tid=51315 A strace session attached to the frozen XBMC shows exactly the same kind of neverending cycles I included in that thread. So, it might very likely be the same problem (vmem allocations). (This post was last modified: 2009-05-26 15:31 by micantox.)
	find quote

micantox Junior Member Posts: 30 Joined: Apr 2009 Reputation: 0	2009-05-29 17:24 Post: #9 Last XBMC Live is affected by the very same bug (here it led to an application crash). Do you think it's time to open a trac ticket with all the information collected so far?
	find quote