During web radio playback and no other (concious) activity with the system, upmpdcli uses up a lot of CPU cycles.The load depicted in the screenshot hovers pretty constantly around 21%:
Afaik, upmpdcli is only responsible for UPNP and OpenHome related activities.
Is there a reason for this even if there is no media transfer going on via upnp?
Could you please check the upmpdcli log file while this happening? You can check where it is located by looking at /etc/upmdcli.conf
If you see nothing, maybe raise the verbosity level and retry. Such a high cpu usage from upmpdcli is unusual, and something is probably going on.
Now I think about it I did notice that upmdcli was sending a surprising number of mpd status commands. I had meant to look into that. I would have assumed it would use idle.
upmpdcli does not use the MPD idle command currently. upmpdcli normally consumes around 0.6% to 1% CPU on a Raspberry PI with one control point connected and monitoring a playing song, so, there is relatively little to optimize, and using idle would make the program a little more complicated (one more thread probably).
But 21% CPU is far too much, and, yes, a first guess might be that upmpdcli is looping on MPD status commands for some reason. We would probably see this in the log.
Thanks for the response. It was some time ago that I noticed the status commands and I can’t remember if they actually resulted in a high CPU load as originally reported here, they may be totally harmless. I need to go back and verify what I see before I lead anyone down the wrong path.
In the mentioned config file I set
logfilename = /var/log/mopidy/upmpdcli.log
loglevel = 6
The higher the loglevel the more it spilled out. There is no trace of an error in it though.
It keeps repeating the following block during web radio playback:
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:upnp-org:serviceId:AVTransport LastChange
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:upnp-org:serviceId:ConnectionManager SinkProtocolInfo
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Product ManufacturerName
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Info DetailsCount
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Volume VolumeMilliDbPerSteps
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Playlist IdArray
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Receiver Metadata
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:av-openhome-org:serviceId:Time Seconds
libupnpp/device/device.cxx:317::UpnpDevice::notifyEvent urn:upnp-org:serviceId:RenderingControl LastChange
src/avtransport.cxx:288::UpMpdAVTransport::getEventDataTransport: <Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT_RCS">
<InstanceID val="0">
<RelativeCounterPosition val="0"/>
<CurrentPlayMode val="NORMAL"/>
<CurrentTrackDuration val="0:00:00"/>
<RelativeTimePosition val="0:00:50"/>
<NumberOfTracks val="1"/>
<RecordStorageMedium val="NOT_IMPLEMENTED"/>
<CurrentRecordQualityMode val="NOT_IMPLEMENTED"/>
<PossiblePlaybackStorageMedia val="HDD,NETWORK"/>
<RecordMediumWriteStatus val="NOT_IMPLEMENTED"/>
<PossibleRecordStorageMedia val="NOT_IMPLEMENTED"/>
<TransportState val="PLAYING"/>
<CurrentTransportActions val="Next,Previous,Pause,Stop,Seek"/>
<AVTransportURI val="http://www.fluxfm.de/stream-berlin"/>
<CurrentTrackURI val="http://www.fluxfm.de/stream-berlin"/>
<TransportStatus val="OK"/>
<TransportPlaySpeed val="1"/>
<PossibleRecordQualityModes val="NOT_IMPLEMENTED"/>
<CurrentTrack val="1"/>
<PlaybackStorageMedium val="HDD"/>
<CurrentMediaDuration val="0:00:00"/>
<AbsoluteTimePosition val="0:00:50"/>
<AbsoluteCounterPosition val="0"/>
<AVTransportURIMetaData val="<?xml version="1.0" encoding="utf-8"?><DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/"><item restricted="1"><dc:title>FluxFM Berlin</dc:title><upnp:class>object.item.audioItem.musicTrack</upnp:class><upnp:originalTrackNumber>0</upnp:originalTrackNumber><res duration="0:00:00" sampleFrequency="44100" audioChannels="2" protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000">http://www.fluxfm.de/stream-berlin</res></item></DIDL-Lite>"/>
<CurrentTrackMetaData val="<?xml version="1.0" encoding="utf-8"?><DIDL-Lite xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/"><item restricted="1"><dc:title>FluxFM Berlin</dc:title><upnp:class>object.item.audioItem.musicTrack</upnp:class><upnp:originalTrackNumber>0</upnp:originalTrackNumber><res duration="0:00:00" sampleFrequency="44100" audioChannels="2" protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_CI=0;DLNA.ORG_FLAGS=01700000000000000000000000000000">http://www.fluxfm.de/stream-berlin</res></item></DIDL-Lite>"/>
</InstanceID>
</Event>If you use tail -f on the output log, the normal “rythm” of things would be one Time event every second, and a bigger bunch of output every 10 S (approximately). Does this look like you are seeing ?
Nothing looks out of place. I guess I’ll have to install PIMusicbox and give it a try. What control point are you using ? This could also be a factor.
Other question: does mpd have a big playlist loaded ? Or just the radio ?
Hi,
watching the tail output the rhythm you’re talking about seems about right. There seems to be even a larger pause between the large block and the time events.
To answer the further questions:
Ever since the CPU consumption is around 20% controlling the thing with bubbleUpnp becomes pretty useless. it takes very long to add stuff to the playlist and generally lags quite badly in all actions.
In addition to the standard musicbox image I installed several further packages not music-related.
Also I tried to get Songcast working (without success) which would be attached to upmpdcli. But I do not have it running.
Hi,
upmpdcli becoming unresponsive in addition to taking CPU makes it look quite like the libupnp problem described in this email thread http://sourceforge.net/p/pupnp/mailman/pupnp-devel/?viewmonth=201501 and this page: http://lesbonscomptes.com/pages/libupnpEvents.html
The short version is that libupnp (on which upmpdcli is based) can become unresponsive when it loses contact with a subscribed control point. This can happen in a varietey of ways. In your case, it does not obviously apply, but the symptoms are curiously similar.
Does the problem persist if you kill and restart upmpdcli while the radio is playing ? You may have to kill -9 when it’s stuck like this.
Hi again,
I installed Pi Musicbox to give the issue a try, and I see nothing special in upmpdcli CPU usage while playing a radio stream. This is one more indication that you are actually experiencing the libupnp problem. I have a fix for this, and I can easily build a raspbian package. Please get in touch with me by email if you want to pursue this: jf at dockes.org
Hi @medoc92 , thanks for the support!
Yes, the problem persists across restarts of both the whole system and the upmpdcli service (via “service upmpdcli restart” or the kill -9 you suggested).
Anyway I’d be willing to try the libupnp fix.
I’ve disabled the Airplay feature using the musicbox web interface.
After a restart the cpu usage seems to be back to normal (for now).
Will monitor it a little tomorrow when the raspi runs a bit longer…
Do Airplay and Upnp have conflicting parts?
UPDATE: False alarm, it did just take a bit longer to reappear this time.
So, updating libupnp6 from the lesbonscomptes repository using “apt-get upgrade” works fine.
The high CPU usage of upmpdcli is gone with that version.
Thanks a lot!
Hi,
As an aside to this discussion, I just added a Raspberry Pi package for sc2mpd (the songcast receiver) to the debian repository on the upmpdcli web site. As far as I can see, this works fine. Just in case you want to try it again…
jf