Possible memory leak in AlsaSink

[richard-ive]

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]

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]

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]

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]

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]

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

[jodal]

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]

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]

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

[richard-ive]

Just a hunch, but it could be to do with:

https://github.com/mopidy/pyspotify/blob/095dd3e3e524bd23feaf909794b5990210792f46/spotify/session.py#L1150-L1151

[jodal]

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]

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.