Possible memory leak in AlsaSink #127

Closed
richard-ive opened this Issue Apr 16, 2014 · 29 comments

Projects

None yet

2 participants

@richard-ive
Contributor
richard@raspberrypi-> python3
Python 3.2.3 (default, Mar  1 2013, 11:53:50)
[GCC 4.6.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import spotify
>>> session = spotify.Session()
>>> loop = spotify.EventLoop(session)
>>> loop.start()
>>> audio = spotify.AlsaSink(session)
>>> session.login('xanox','secret')
>>> track = session.get_track('spotify:track:1XyP2v40e7Xv7XhB9d2rDo')
>>> track.load()
Track('spotify:track:1XyP2v40e7Xv7XhB9d2rDo')
>>> session.player.load(track)
>>> session.player.play()

Over a 15 minute window I checked the memory usage:

richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        152        333          0         25         42
-/+ buffers/cache:         84        400
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        162        322          0         25         42
-/+ buffers/cache:         94        391
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        179        306          0         25         44
-/+ buffers/cache:        109        375
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        187        297          0         25         44
-/+ buffers/cache:        117        367
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        277        208          0         49         48
-/+ buffers/cache:        178        306
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        359        126          0         62         53
-/+ buffers/cache:        243        241
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        389         96          0         62         55
-/+ buffers/cache:        271        214
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        390         94          0         62         55
-/+ buffers/cache:        272        212
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        390         94          0         62         55
-/+ buffers/cache:        272        212
Swap:           99         34         65
[~]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        390         94          0         62         55
-/+ buffers/cache:        272        212
Swap:           99         34         65
[~]

Then, after stopping and unloading the player:

>>> session.player.play(False)
>>> session.player.unload()
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        391         94          0         62         55
-/+ buffers/cache:        272        212
Swap:           99         34         65
@jodal jodal added 2.x bug labels Apr 16, 2014
@jodal jodal added this to the v2.0.0b1 milestone Apr 16, 2014
@jodal
Member
jodal commented Apr 16, 2014

This is a long track of 32 minutes. Still, I don't like the fact that the memory usage stays high after playback is stopped and the track unloaded.

Can you observe the same memory growth if you don't connect an audio sink, but instead just ask libspotify to prefetch the audio data using session.player.prefetch(track)?

How is memory usage when you unload the track again?

@richard-ive
Contributor

I tried to illustrate the problem using continuous playback - hence the long track - in hindsight the buffer size would be a lot larger to accommodate the larger file. My bad!

Anyway, I'll post my findings using prefetch shortly!

On 16 Apr 2014, at 18:46, Stein Magnus Jodal notifications@github.com wrote:

This is a long track of 32 minutes. Still, I don't like the fact that the memory usage stays high after playback is stopped and the track unloaded.

Can you observe the same memory growth if you don't connect an audio sink, but instead just ask libspotify to prefetch the audio data using session.player.prefetch(track)?

How is memory usage when you unload the track again?


Reply to this email directly or view it on GitHub.

@richard-ive
Contributor
richard@raspberrypi-> python3
Python 3.2.3 (default, Mar  1 2013, 11:53:50)
[GCC 4.6.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import spotify
>>> session = spotify.Session()
>>> loop = spotify.EventLoop(session)
>>> loop.start()
>>> audio = spotify.AlsaSink(session)
>>> session.login('xanox','x')
>>> track = session.get_track('spotify:track:1XyP2v40e7Xv7XhB9d2rDo')
>>> track.load()
Track('spotify:track:1XyP2v40e7Xv7XhB9d2rDo')
>>> session.player.prefetch(track)
>>> session.player.load(track)
>>> session.player.play()
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        229        255          0         66         44
-/+ buffers/cache:        119        365
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        235        249          0         66         46
-/+ buffers/cache:        123        361
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> echo "JUST BEFORE PRETECH"
JUST BEFORE PRETECH
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        236        248          0         66         46
-/+ buffers/cache:        123        361
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        236        248          0         66         46
-/+ buffers/cache:        123        361
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        236        248          0         66         46
-/+ buffers/cache:        123        361
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        236        248          0         66         46
-/+ buffers/cache:        123        361
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        236        248          0         66         46
-/+ buffers/cache:        123        361
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> alsamixer
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        242        243          0         66         48
-/+ buffers/cache:        127        357
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        242        242          0         66         48
-/+ buffers/cache:        127        357
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        242        242          0         66         48
-/+ buffers/cache:        128        357
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        242        242          0         66         48
-/+ buffers/cache:        128        356
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        248        236          0         66         48
-/+ buffers/cache:        133        351
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         66         50
-/+ buffers/cache:        158        326
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        298        186          0         66         52
-/+ buffers/cache:        180        305
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> top
top - 20:45:06 up 1 day,  3:37,  2 users,  load average: 0.14, 0.14, 0.11
Tasks:  83 total,   1 running,  82 sleeping,   0 stopped,   0 zombie
%Cpu(s):  6.4 us,  4.5 sy,  0.0 ni, 89.1 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:    496948 total,   308864 used,   188084 free,    67840 buffers
KiB Swap:   102396 total,    25004 used,    77392 free,    53928 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND
 7553 richard   20   0 98152  77m 5308 S   8.7 16.0   0:47.48 python3
 2084 root      20   0 16776 9684 1524 S   0.0  1.9  15:48.37 python
 7563 richard   20   0  6852 4100 1628 S   0.0  0.8   0:02.21 bash
 7531 richard   20   0  6848 4084 1612 S   0.0  0.8   0:01.77 bash
 7523 root      20   0  9808 3196 2572 S   0.0  0.6   0:00.58 sshd
 7555 root      20   0  9808 3196 2572 S   0.0  0.6   0:00.57 sshd
 2283 root      20   0 26524 1732 1400 S   0.0  0.3   0:01.19 console-kit-dae
 7530 richard   20   0  9808 1628  996 S   0.0  0.3   0:00.21 sshd
 7562 richard   20   0  9808 1628  996 S   0.6  0.3   0:00.26 sshd
 7635 richard   20   0  4668 1368 1028 R   1.9  0.3   0:00.21 top
 1976 www-data  20   0 26472 1288  900 S   0.0  0.3   0:00.02 apache2
 2350 root      20   0 22320 1156  844 S   0.0  0.2   0:00.60 polkitd
 1966 www-data  20   0 26480 1092  724 S   0.0  0.2   0:00.03 apache2
 2215 postgres  20   0 46188  860  604 S   0.0  0.2   0:10.33 postgres
 7229 www-data  20   0 26432  796  600 S   0.0  0.2   0:00.00 apache2
 1881 root      20   0 18820  764  560 S   0.0  0.2   0:01.52 smbd
 1988 messageb  20   0  3316  608  432 S   0.0  0.1   0:00.29 dbus-daemon
[~/dev/python/sponos]
richard@raspberrypi-> top
top - 20:46:41 up 1 day,  3:39,  2 users,  load average: 0.07, 0.12, 0.10
Tasks:  83 total,   1 running,  82 sleeping,   0 stopped,   0 zombie
%Cpu(s):  6.8 us,  1.3 sy,  0.0 ni, 91.4 id,  0.4 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem:    496948 total,   330688 used,   166260 free,    67848 buffers
KiB Swap:   102396 total,    25004 used,    77392 free,    55464 cached

  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND
 7638 richard   20   0  4664 1288  956 R  14.8  0.3   0:00.08 top
 7553 richard   20   0  115m  97m 5308 S   9.8 20.1   0:55.86 python3
    1 root      20   0  2144   76   48 S   0.0  0.0   0:04.37 init
    2 root      20   0     0    0    0 S   0.0  0.0   0:00.01 kthreadd
    3 root      20   0     0    0    0 S   0.0  0.0   0:12.64 ksoftirqd/0
    5 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 kworker/0:0H
    7 root      20   0     0    0    0 S   0.0  0.0   0:09.33 rcu_preempt
    8 root      20   0     0    0    0 S   0.0  0.0   0:00.00 rcu_bh
    9 root      20   0     0    0    0 S   0.0  0.0   0:00.00 rcu_sched
   10 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 khelper
   11 root      20   0     0    0    0 S   0.0  0.0   0:00.01 kdevtmpfs
   12 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 netns
   14 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 writeback
   15 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 bioset
   16 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 kblockd
   17 root      20   0     0    0    0 S   0.0  0.0   0:00.13 khubd
   18 root       0 -20     0    0    0 S   0.0  0.0   0:00.00 rpciod
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        323        161          0         66         54
-/+ buffers/cache:        203        282
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        352        132          0         66         56
-/+ buffers/cache:        230        255
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        386         98          0         66         58
-/+ buffers/cache:        261        223
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        398         86          0         66         59
-/+ buffers/cache:        272        212
Swap:           99         24         75
[~/dev/python/sponos]
@richard-ive
Contributor

After session.player.play(False):

richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        442         42          0         66         62
-/+ buffers/cache:        313        171
Swap:           99         24         75
[~/dev/python/sponos]

After session.player.unload():

richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        443         42          0         66         62
-/+ buffers/cache:        314        170
Swap:           99         24         75
[~/dev/python/sponos]
@richard-ive
Contributor

Once the track has been stopped and unloaded the memory consumption stops, but it doesn't appear to free up.

@jodal
Member
jodal commented Apr 16, 2014

Your example doesn't tell if the memory usage grows at prefetch() or at load() and play(). I'm interested in if there's any memory leak when just doing prefetch(), preferable without the AlsaSink being instantiated at all.

If there's no memory leak with just prefetch(), it's interesting to know if there's a memory leak with load() and play() without AlsaSink.

This will help pinpoint if the memory leak is in libspotify/prefetch, the pyspotify event system, or in AlsaSink itself.

@richard-ive
Contributor

Does this help?

richard@raspberrypi-> python3
Python 3.2.3 (default, Mar  1 2013, 11:53:50)
[GCC 4.6.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import spotify
>>> session = spotify.Session()
>>> loop = spotify.EventLoop(session)
>>> loop.start()
>>> session.login('xanox','xxx')
>>> track = session.get_track('spotify:track:13qqdlSeF8FcxsRyapDMZ0')
>>> track.load()
Track('spotify:track:13qqdlSeF8FcxsRyapDMZ0')
>>> session.player.prefetch(track)
>>> session.player.load(track)
>>> session.player.play()
>>> audio = spotify.AlsaSink(session)
[~/dev/python/sponos]
richard@raspberrypi-> echo "BEFORE PREFETCH \/\/\/"
BEFORE PREFETCH \/\/\/
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         67         83
-/+ buffers/cache:        125        360
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFTER PREFETCH \/\/\/"
AFTER PREFETCH \/\/\/
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         67         83
-/+ buffers/cache:        125        360
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         67         83
-/+ buffers/cache:        125        360
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         67         83
-/+ buffers/cache:        125        360
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         67         83
-/+ buffers/cache:        125        360
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         67         83
-/+ buffers/cache:        125        360
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         67         83
-/+ buffers/cache:        125        360
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        275        209          0         67         83
-/+ buffers/cache:        125        360
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFER LOAD \/\/\/"
AFER LOAD \/\/\/
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        277        207          0         67         84
-/+ buffers/cache:        125        359
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        277        207          0         67         84
-/+ buffers/cache:        125        359
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        278        207          0         67         84
-/+ buffers/cache:        126        358
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        278        207          0         67         84
-/+ buffers/cache:        126        358
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFER PLAY \/\/\/"
AFER PLAY \/\/\/
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        278        207          0         67         84
-/+ buffers/cache:        126        358
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        278        207          0         67         84
-/+ buffers/cache:        126        358
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        278        207          0         67         84
-/+ buffers/cache:        126        358
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        278        207          0         67         84
-/+ buffers/cache:        126        358
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        278        207          0         67         84
-/+ buffers/cache:        126        358
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFER IMPORTING ALSASINK \/\/\/"
AFER IMPORTING ALSASINK \/\/\/
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        281        204          0         67         84
-/+ buffers/cache:        129        355
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        284        200          0         67         85
-/+ buffers/cache:        132        353
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        287        197          0         67         85
-/+ buffers/cache:        135        349
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        290        195          0         67         85
-/+ buffers/cache:        137        347
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        301        183          0         67         86
-/+ buffers/cache:        147        337
Swap:           99         24         75
[~/dev/python/sponos]
richard@raspberrypi->

A short debug output

DEBUG:spotify.session:Music delivery of 416 frames, 416 consumed
DEBUG:spotify.session:Audio buffer stats requested, but no listener
DEBUG:spotify.session:Music delivery of 2048 frames, 2048 consumed
DEBUG:spotify.session:Music delivery of 2048 frames, 2048 consumed
DEBUG:spotify.session:Music delivery of 2048 frames, 2048 consumed
DEBUG:spotify.session:Music delivery of 2048 frames, 1820 consumed
DEBUG:spotify.session:Music delivery of 228 frames, 228 consumed
DEBUG:spotify.session:Music delivery of 2048 frames, 224 consumed
DEBUG:spotify.session:Music delivery of 1824 frames, 0 consumed
DEBUG:spotify.session:Audio buffer stats requested, but no listener
DEBUG:spotify.session:Audio buffer stats requested, but no listener
@jodal
Member
jodal commented Apr 17, 2014

I agree, this clearly shows AlsaSink as the culprit. I'll try to reproduce it myself.

@jodal
Member
jodal commented Apr 17, 2014

The ffi.buffer() call just creates a buffer view on the audio data in libspotify's memory. The buffer_[:] line copies the audio buffer to "Python space", so we own it ourselves and can pass it on without thinking about the life cycle of the audio buffer in "C space".

The size of this bytestring is in the range of 4_2048 to 4_22050 bytes per audio delivery, depending on their frequency. Per second, we're talking about 4*44100=176400 bytes of data that is copied once from libspotify to Python and then passed on to ALSA, probably causing a second copy. No references to this data is kept for later, so the total memory usage from this pipeline shouldn't be growing over time.

@jodal
Member
jodal commented Apr 17, 2014

I've tested a bit myself now, and I can see that the memory usage grows when importing spotify, when creating the session, when creating the audio sink, and when starting playback. Though, the memory usage on my system is stable throughout the playback of a track of 329 seconds. If I manually do audio._close() after playback is done I can reduce the memory usage somewhat, but that is only temporary until the next track is played.

@jodal jodal removed this from the v2.0.0b1 milestone Apr 17, 2014
@jodal jodal added question and removed question labels Apr 17, 2014
@richard-ive
Contributor

Can you supply the other of commands you used so I can test on my Pi?

@jodal
Member
jodal commented Apr 17, 2014

I've just used free -m and htop, watching the VIRT and RSS columns of my Python process.

With the exception of my choice of a shorter track, I've done exactly the same as you've done above.

@jodal jodal self-assigned this Apr 17, 2014
@jodal
Member
jodal commented Apr 17, 2014

One thing you can try just for debugging is: after having played a track, and unload()-ed it again, is to try to close the ALSA device to see how much memory that will release:

audio._close()
@richard-ive
Contributor
richard@raspberrypi-> python3
importPython 3.2.3 (default, Mar  1 2013, 11:53:50)
[GCC 4.6.3] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> import spotify
>>> session = spotify.Session()
>>> loop = spotify.EventLoop(session)
>>> loop.start()
>>> session.login('xanox','x')
>>> track = session.get_track('spotify:track:13qqdlSeF8FcxsRyapDMZ0')
>>> track.load()
Track('spotify:track:13qqdlSeF8FcxsRyapDMZ0')
>>> session.player.load(track)
>>> session.player.play()
>>> audio = spotify.AlsaSink(session)
>>> session.player.unload()
>>> audio._close()
richard@raspberrypi-> echo "BEFORE LOAD"
BEFORE LOAD
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        256        228          0         60         71
-/+ buffers/cache:        124        360
Swap:           99         22         77
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFTER LOAD"
AFTER LOAD
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        259        226          0         60         73
-/+ buffers/cache:        125        359
Swap:           99         22         77
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFTER PLAY START"
AFTER PLAY START
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        259        225          0         60         73
-/+ buffers/cache:        125        359
Swap:           99         22         77
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFTER ALSA LOAD"
AFTER ALSA LOAD
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        260        224          0         60         73
-/+ buffers/cache:        126        358
Swap:           99         22         77
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        263        222          0         60         73
-/+ buffers/cache:        128        356
Swap:           99         22         77
[~/dev/python/sponos]
richard@raspberrypi-> echo "BEFORE UNLOAD"
BEFORE UNLOAD
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        352        132          0         60         78
-/+ buffers/cache:        213        271
Swap:           99         22         77
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFTER UNLOAD"
AFTER UNLOAD
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        353        131          0         60         78
-/+ buffers/cache:        214        270
Swap:           99         22         77
[~/dev/python/sponos]
richard@raspberrypi-> echo "AFTER AUDIO CLOSE"
AFTER AUDIO CLOSE
[~/dev/python/sponos]
richard@raspberrypi-> free -m
             total       used       free     shared    buffers     cached
Mem:           485        354        130          0         60         78
-/+ buffers/cache:        214        270
Swap:           99         22         77
[~/dev/python/sponos]
richard@raspberrypi->
@richard-ive
Contributor

I thought, as I'm using Raspian's hard float armv6 version of libspotify (which is currently in beta), it may be an issue within the libspotify source. But, having run jukebox.c for an extended period of time, the memory usage was fairly stable.

@richard-ive
Contributor

Any further pointers to try and debug this one?

@jodal
Member
jodal commented Apr 28, 2014

I'm planning to try to reproduce this on one of my own Raspberry Pis, and with longer tracks now when I'm back on proper Internet.

@jodal
Member
jodal commented May 2, 2014

I've now tried to reproduce on a Raspberry Pi running Raspbian (armhf, in other words) updated a couple of days ago.

I used pyspotify2 as of today, commit f528745. Exact command executed was:

$ cd examples/
$ python play_track.py spotify:track:0D6IH8Q6rFjsmOIsg6rFlG

This command requires that you already have cached credentials in place, which you can create like this:

>>> import spotify
>>> session = spotify.Session()
>>> loop = spotify.EventLoop(session)
>>> loop.start()
>>> session.login('me', 'secret', remember_me=True)  # The `remember_me` part is important
>>> session.connection.state
<ConnectionState.LOGGED_IN: 1>
>>> spotify.logout()  # Important for proper flushing to disk
>>> session.connection.state
<ConnectionState.LOGGED_OUT: 0>

The track used lasts for 79 minutes, which should be enough to make most memory leaks visible. Before I started Python, memory usage was at 84MB (free -m, "Used", "-/+ buffers/cache"). After running for a few minutes memory usage was at 101MB. After running for 30-60 minutes more, memory usage was still at 101MB.

In other words, I'm not able to reproduce this issue.

@jodal jodal closed this May 2, 2014
@richard-ive
Contributor

With a brand new pi + new install of Raspbian Wheezy the memory usage isn't any better..

what versions of pyalsaudio and stuff are you running?

@jodal
Member
jodal commented May 4, 2014
(venv)jodal@raspi-armhf:~/dev/pyspotify2:v2.x/develop$ pip list
argparse (1.2.1)
cffi (0.8.2)
pip (1.5.4)
pyalsaaudio (0.7)
pycparser (2.10)
pyspotify (2.0.0b3, /home/jodal/dev/pyspotify2)
setuptools (2.2)
wsgiref (0.1.2)
(venv)jodal@raspi-armhf:~/dev/pyspotify2:v2.x/develop$ dpkg -l | grep alsa
ii  alsa-base                             1.0.25+3                            all          ALSA driver configuration files
ii  alsa-utils                            1.0.27.2-1                          armhf        Utilities for configuring and using ALSA
ii  gstreamer0.10-alsa:armhf              0.10.36-1.1                         armhf        GStreamer plugin for ALSA
(venv)jodal@raspi-armhf:~/dev/pyspotify2:v2.x/develop$ dpkg -l | grep asound
ii  libasound2:armhf                      1.0.27.2-3                          armhf        shared library for ALSA applications
ii  libasound2-data                       1.0.27.2-3                          all          Configuration files and profiles for ALSA drivers
ii  libasound2-dev:armhf                  1.0.27.2-3                          armhf        shared library for ALSA applications -- development files
ii  libasound2-plugins:armhf              1.0.27-2+b2                         armhf        ALSA library additional plugins
@jodal jodal reopened this May 4, 2014
@richard-ive
Contributor
richard@raspberrypi:~/dev/python/pyspotify$ dpkg -l | grep alsa
ii  alsa-base                             1.0.25+3~deb7u1                         all          ALSA driver configuration files
ii  alsa-utils                            1.0.25-4                                armhf        Utilities for configuring and using ALSA
richard@raspberrypi:~/dev/python/pyspotify$ dpkg -l | grep asound
ii  libasound2:armhf                      1.0.25-4                                armhf        shared library for ALSA applications
ii  libasound2-dev:armhf                  1.0.25-4                                armhf        shared library for ALSA applications -- development files
ii  libasound2-plugins:armhf              1.0.25-2                                armhf        ALSA library additional plugins

different versions so i'll try getting those upgraded.

@richard-ive
Contributor

Just got a new SD card and it's still an issue.

What's in your /etc/apt/sources.list?

deb http://mirrordirector.raspbian.org/raspbian/ wheezy main contrib non-free rpi

my apt doesn't find 1.0.27.2-3 for alsa-utils.

@richard-ive
Contributor

It would appear that Python 3.2.3 is the culprit.

Running your suggested commands on Python 2.7.3 gives me much better memory (and CPU) stability!

@jodal
Member
jodal commented May 5, 2014

Great! I can reproduce on Python 3.3 and 3.4. Will look more into this.

For the record, I'm running the testing/jessie version of Raspbian. My /etc/sources.list look like this:

deb http://mirrordirector.raspbian.org/raspbian/ jessie main contrib non-free rpi
@jodal
Member
jodal commented May 8, 2014

Test Setup

Testing on MacBook Air 2011 model, running Ubuntu 14.04 amd64. pyspotify v2.0.0b3 and all dependencies are installed in virtualenvs, including pyalsaaudio 0.7.

Tested using examples/play_track.py from pyspotify with this exact command:

python play_track.py http://open.spotify.com/track/0D6IH8Q6rFjsmOIsg6rFlG

Results

Test Python 2.7.6 Python 3.4.0
play_track.py RSS stable at 27MB RSS growing steadily
Without audio sink RSS stable at 25MB RSS stable at 24MB
Audio sink without writing to ALSA RSS stable at 25MB RSS stable at 24MB
Audio sink with PCM_NORMAL RSS stable at 27 MB RSS growing steadily

Conclusion: The memory leak is clearly in the ALSA part, and not elsewhere in pyspotify or in pyspotify's event system delivering the audio data to the AlsaSink.

Reproducing with just pyalsaaudio

I created the following script to try to reproduce the issue without pyspotify involved:

from __future__ import print_function

import resource
import time

import alsaaudio

seconds = 0
max_rss = 0
device = alsaaudio.PCM()

while True:
    device.write(b'\x00' * 44100)
    time.sleep(1)
    seconds += 1
    if seconds % 10 == 0:
        prev_rss = max_rss
        max_rss = resource.getrusage(resource.RUSAGE_SELF).ru_maxrss
        diff_rss = max_rss - prev_rss
        print('After %ds: max RSS %d kB, increased %d kB' % (
            seconds, max_rss, diff_rss))

Which gave the following results on Python 2.7.6:

$ python --version
Python 2.7.6
$ python pyalsaaudio-memory-leak.py 
After 10s: max RSS 6740 kB, increased 6740 kB
After 20s: max RSS 6740 kB, increased 0 kB
After 30s: max RSS 6740 kB, increased 0 kB
After 40s: max RSS 6740 kB, increased 0 kB
After 50s: max RSS 6740 kB, increased 0 kB
After 60s: max RSS 6740 kB, increased 0 kB
After 70s: max RSS 6740 kB, increased 0 kB
After 80s: max RSS 6740 kB, increased 0 kB
After 90s: max RSS 6740 kB, increased 0 kB
After 100s: max RSS 6740 kB, increased 0 kB
After 110s: max RSS 6740 kB, increased 0 kB
After 120s: max RSS 6740 kB, increased 0 kB
After 130s: max RSS 6740 kB, increased 0 kB
After 140s: max RSS 6740 kB, increased 0 kB
After 150s: max RSS 6740 kB, increased 0 kB
After 160s: max RSS 6740 kB, increased 0 kB
After 170s: max RSS 6740 kB, increased 0 kB
After 180s: max RSS 6740 kB, increased 0 kB

And on Python 3.4.0:

$ python --version
Python 3.4.0
$ python pyalsaaudio-memory-leak.py 
After 10s: max RSS 8252 kB, increased 8252 kB
After 20s: max RSS 8516 kB, increased 264 kB
After 30s: max RSS 9044 kB, increased 528 kB
After 40s: max RSS 9572 kB, increased 528 kB
After 50s: max RSS 9836 kB, increased 264 kB
After 60s: max RSS 10364 kB, increased 528 kB
After 70s: max RSS 10664 kB, increased 300 kB
After 80s: max RSS 11192 kB, increased 528 kB
After 90s: max RSS 11720 kB, increased 528 kB
After 100s: max RSS 11984 kB, increased 264 kB
After 110s: max RSS 12512 kB, increased 528 kB
After 120s: max RSS 13040 kB, increased 528 kB
After 130s: max RSS 13304 kB, increased 264 kB
After 140s: max RSS 13832 kB, increased 528 kB
After 150s: max RSS 14360 kB, increased 528 kB
After 160s: max RSS 14624 kB, increased 264 kB
After 170s: max RSS 15152 kB, increased 528 kB
After 180s: max RSS 15416 kB, increased 264 kB

The growth seems to be about (15416kB - 8252kB) / (180s - 10s) = 42.14 kB/s. This is peculiarly close to the 43.07 kB (44100 bytes / 1024) of fake audio data we throw at pyalsaaudio every second.

With pyspotify, we throw four times as much data on pyalsaaudio (16-bit stereo audio, not 8-bit mono like we fake here), so the memory growth will probably be four times faster in real life.

@jodal
Member
jodal commented May 8, 2014

I can confirm that the memory leak also is present on Python 3.2.5:

$ python --version
Python 3.2.5
$ python pyalsaaudio-memory-leak.py 
After 10s: max RSS 9604 kB, increased 9604 kB
After 20s: max RSS 9904 kB, increased 300 kB
After 30s: max RSS 10432 kB, increased 528 kB
After 40s: max RSS 10696 kB, increased 264 kB
After 50s: max RSS 11224 kB, increased 528 kB
After 60s: max RSS 11644 kB, increased 420 kB
After 70s: max RSS 12172 kB, increased 528 kB
After 80s: max RSS 12436 kB, increased 264 kB
After 90s: max RSS 12964 kB, increased 528 kB
After 100s: max RSS 13492 kB, increased 528 kB
After 110s: max RSS 13756 kB, increased 264 kB
After 120s: max RSS 14284 kB, increased 528 kB
After 130s: max RSS 14812 kB, increased 528 kB
After 140s: max RSS 15076 kB, increased 264 kB
After 150s: max RSS 15604 kB, increased 528 kB
After 160s: max RSS 15868 kB, increased 264 kB
After 170s: max RSS 16396 kB, increased 528 kB
After 180s: max RSS 16924 kB, increased 528 kB

If I quadruple the amount of audio data, the memory growth quadruples as well:

$ python --version
Python 3.4.0
$ python pyalsaaudio-memory-leak.py 
After 10s: max RSS 9624 kB, increased 9624 kB
After 20s: max RSS 11208 kB, increased 1584 kB
After 30s: max RSS 13056 kB, increased 1848 kB
After 40s: max RSS 14904 kB, increased 1848 kB
After 50s: max RSS 16488 kB, increased 1584 kB
After 60s: max RSS 18336 kB, increased 1848 kB
After 70s: max RSS 20184 kB, increased 1848 kB
After 80s: max RSS 21768 kB, increased 1584 kB
After 90s: max RSS 23616 kB, increased 1848 kB
After 100s: max RSS 25464 kB, increased 1848 kB
After 110s: max RSS 27048 kB, increased 1584 kB
After 120s: max RSS 28896 kB, increased 1848 kB
After 130s: max RSS 30744 kB, increased 1848 kB
After 140s: max RSS 32328 kB, increased 1584 kB
After 150s: max RSS 34176 kB, increased 1848 kB
After 160s: max RSS 36024 kB, increased 1848 kB
After 170s: max RSS 37608 kB, increased 1584 kB
After 180s: max RSS 39456 kB, increased 1848 kB
@jodal
Member
jodal commented May 8, 2014
@jodal jodal added a commit that closed this issue May 8, 2014
@jodal jodal sink: Warn about pyalsaaudio memory leak
Fixes #127
5079ec7
@jodal jodal closed this in 5079ec7 May 8, 2014
@jodal jodal added this to the v2.0.0b4 milestone May 9, 2014
@jodal
Member
jodal commented May 8, 2015

This bug was fixed today in larsimmisch/pyalsaaudio@5e8a08b.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment