search

hzeller / gmrender-resurrect

Resource efficient UPnP/DLNA renderer, optimal for Raspberry Pi, CuBox or a general MediaServer. Fork of GMediaRenderer to add some features to make it usable.
GNU General Public License v2.0
832 stars 202 forks source link

Songs take 10-30s to start playing on RPi, same to seek #82

Open mr-smidge opened 9 years ago

mr-smidge commented 9 years ago

Hello,

I've set up gmrender-resurrect on my RPi Model B as an audio player, but have noticed that it takes a very long time for a song to actually start playing after selecting the track, between 10-30s. It takes a similar amount of time for music to resume after seeking within a track. The track elapsed time doesn't increase: it's a delay where nothing happens until the music plays.

Reproducible with:

Log extract using mediatomb as server (notice timestamps between LastChange and CurrentTrackDuration, around 12 seconds):

INFO  [2015-05-23 16:59:03.984180 | transport] AVTransportURI: http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac
INFO  [2015-05-23 16:59:03.985479 | transport] AVTransportURIMetaData: <DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:sec="http://www.sec.co.kr/"><item id="67358" parentID="10" restricted="1"><upnp:class>object.item.audioItem.musicTrack</upnp:class><dc:title>(Slip &amp; Slide) Suicide</dc:title><dc:creator>Kosheen</dc:creator><upnp:artist>Kosheen</upnp:artist><upnp:genre>Drum &amp; Bass</upnp:genre><dc:date>2001-01-01</dc:date><upnp:album>Resist (Moksha Recordings)</upnp:album><upnp:originalTrackNumber>6</upnp:originalTrackNumber><res protocolInfo="http-get:*:audio/x-flac:DLNA.ORG_FLAGS=01700000000000000000000000000000;DLNA.ORG_OP=01" bitrate="131584" sampleFrequency="44100" nrAudioChannels="2" size="27634564" duration="0:03:35.000">http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac</res></item></DIDL-Lite>
INFO  [2015-05-23 16:59:03.987076 | transport] NumberOfTracks: 1
INFO  [2015-05-23 16:59:03.988467 | gstreamer] Set uri to 'http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac'
INFO  [2015-05-23 16:59:03.990878 | transport] LastChange: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<AVTransportURI val="http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac"></AVTransportURI>
<AVTransportURIMetaData val="&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:sec=&quot;http://www.sec.co.kr/&quot;&gt;&lt;item id=&quot;67358&quot; parentID=&quot;10&quot; restricted=&quot;1&quot;&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;dc:title&gt;(Slip &amp;amp; Slide) Suicide&lt;/dc:title&gt;&lt;dc:creator&gt;Kosheen&lt;/dc:creator&gt;&lt;upnp:artist&gt;Kosheen&lt;/upnp:artist&gt;&lt;upnp:genre&gt;Drum &amp;amp; Bass&lt;/upnp:genre&gt;&lt;dc:date&gt;2001-01-01&lt;/dc:date&gt;&lt;upnp:album&gt;Resist (Moksha Recordings)&lt;/upnp:album&gt;&lt;upnp:originalTrackNumber&gt;6&lt;/upnp:originalTrackNumber&gt;&lt;res protocolInfo=&quot;http-get:*:audio/x-flac:DLNA.ORG_FLAGS=01700000000000000000000000000000;DLNA.ORG_OP=01&quot; bitrate=&quot;131584&quot; sampleFrequency=&quot;44100&quot; nrAudioChannels=&quot;2&quot; size=&quot;27634564&quot; duration=&quot;0:03:35.000&quot;&gt;http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac&lt;/res&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"></AVTransportURIMetaData>
<NumberOfTracks val="1"></NumberOfTracks>
</InstanceID>
</Event>
INFO  [2015-05-23 16:59:04.873291 | transport] TransportState: PLAYING
INFO  [2015-05-23 16:59:04.874528 | transport] CurrentTransportActions: PAUSE,STOP,SEEK
INFO  [2015-05-23 16:59:04.875636 | transport] CurrentTrack: 1
INFO  [2015-05-23 16:59:04.876744 | transport] CurrentTrackURI: http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac
INFO  [2015-05-23 16:59:04.877880 | transport] CurrentTrackMetaData: <DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:sec="http://www.sec.co.kr/"><item id="67358" parentID="10" restricted="1"><upnp:class>object.item.audioItem.musicTrack</upnp:class><dc:title>(Slip &amp; Slide) Suicide</dc:title><dc:creator>Kosheen</dc:creator><upnp:artist>Kosheen</upnp:artist><upnp:genre>Drum &amp; Bass</upnp:genre><dc:date>2001-01-01</dc:date><upnp:album>Resist (Moksha Recordings)</upnp:album><upnp:originalTrackNumber>6</upnp:originalTrackNumber><res protocolInfo="http-get:*:audio/x-flac:DLNA.ORG_FLAGS=01700000000000000000000000000000;DLNA.ORG_OP=01" bitrate="131584" sampleFrequency="44100" nrAudioChannels="2" size="27634564" duration="0:03:35.000">http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac</res></item></DIDL-Lite>
INFO  [2015-05-23 16:59:04.882603 | transport] LastChange: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<TransportState val="PLAYING"></TransportState>
<CurrentTransportActions val="PAUSE,STOP,SEEK"></CurrentTransportActions>
<CurrentTrack val="1"></CurrentTrack>
<CurrentTrackURI val="http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac"></CurrentTrackURI>
<CurrentTrackMetaData val="&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:sec=&quot;http://www.sec.co.kr/&quot;&gt;&lt;item id=&quot;67358&quot; parentID=&quot;10&quot; restricted=&quot;1&quot;&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;dc:title&gt;(Slip &amp;amp; Slide) Suicide&lt;/dc:title&gt;&lt;dc:creator&gt;Kosheen&lt;/dc:creator&gt;&lt;upnp:artist&gt;Kosheen&lt;/upnp:artist&gt;&lt;upnp:genre&gt;Drum &amp;amp; Bass&lt;/upnp:genre&gt;&lt;dc:date&gt;2001-01-01&lt;/dc:date&gt;&lt;upnp:album&gt;Resist (Moksha Recordings)&lt;/upnp:album&gt;&lt;upnp:originalTrackNumber&gt;6&lt;/upnp:originalTrackNumber&gt;&lt;res protocolInfo=&quot;http-get:*:audio/x-flac:DLNA.ORG_FLAGS=01700000000000000000000000000000;DLNA.ORG_OP=01&quot; bitrate=&quot;131584&quot; sampleFrequency=&quot;44100&quot; nrAudioChannels=&quot;2&quot; size=&quot;27634564&quot; duration=&quot;0:03:35.000&quot;&gt;http://192.168.0.25:49152/content/media/object_id/67358/res_id/0/ext/file.flac&lt;/res&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"></CurrentTrackMetaData>
</InstanceID>
</Event>
INFO  [2015-05-23 16:59:16.886879 | transport] CurrentTrackDuration: 0:03:35
INFO  [2015-05-23 16:59:16.888263 | transport] LastChange: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<CurrentTrackDuration val="0:03:35"></CurrentTrackDuration>
</InstanceID>
</Event>
INFO  [2015-05-23 16:59:17.893587 | transport] RelativeTimePosition: 0:00:01
INFO  [2015-05-23 16:59:18.899059 | transport] RelativeTimePosition: 0:00:02
INFO  [2015-05-23 16:59:19.903911 | transport] RelativeTimePosition: 0:00:03

Log extract with seeking (again, notice timestamps - 12 seconds to skip):

INFO  [2015-05-23 17:00:24.881794 | transport] RelativeTimePosition: 0:01:08
INFO  [2015-05-23 17:00:25.886703 | transport] RelativeTimePosition: 0:01:09
INFO  [2015-05-23 17:00:26.892409 | transport] RelativeTimePosition: 0:01:10
INFO  [2015-05-23 17:00:27.897582 | transport] RelativeTimePosition: 0:01:11
INFO  [2015-05-23 17:00:39.410390 | transport] RelativeTimePosition: 0:02:03
INFO  [2015-05-23 17:00:40.416544 | transport] RelativeTimePosition: 0:02:04
INFO  [2015-05-23 17:00:41.422185 | transport] RelativeTimePosition: 0:02:05

Log extract using local server on a Android 4.4.2 phone (11 seconds):

INFO  [2015-05-23 17:00:59.336191 | transport] AVTransportURI: http://192.168.0.6:57645/external/audio/media/23.mp3
INFO  [2015-05-23 17:00:59.337494 | transport] AVTransportURIMetaData: <DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:sec="http://www.sec.co.kr/"><item id="/external/audio/media/23" parentID="/external/audio/media" restricted="1"><upnp:class>object.item.audioItem.musicTrack</upnp:class><dc:title>Over the horizon</dc:title><dc:creator>Samsung</dc:creator><upnp:artist>Samsung</upnp:artist><upnp:albumArtURI>http://192.168.0.6:57645/external/audio/albums/7.jpg</upnp:albumArtURI><upnp:genre>New Age</upnp:genre><dc:date>0</dc:date><upnp:album>Samsung</upnp:album><upnp:originalTrackNumber>0</upnp:originalTrackNumber><res protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_FLAGS=01700000000000000000000000000000" bitrate="16000" size="2705618" duration="0:02:35.000">http://192.168.0.6:57645/external/audio/media/23.mp3</res></item></DIDL-Lite>
INFO  [2015-05-23 17:00:59.339299 | gstreamer] Set uri to 'http://192.168.0.6:57645/external/audio/media/23.mp3'
INFO  [2015-05-23 17:00:59.341901 | transport] LastChange: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<AVTransportURI val="http://192.168.0.6:57645/external/audio/media/23.mp3"></AVTransportURI>
<AVTransportURIMetaData val="&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:sec=&quot;http://www.sec.co.kr/&quot;&gt;&lt;item id=&quot;/external/audio/media/23&quot; parentID=&quot;/external/audio/media&quot; restricted=&quot;1&quot;&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;dc:title&gt;Over the horizon&lt;/dc:title&gt;&lt;dc:creator&gt;Samsung&lt;/dc:creator&gt;&lt;upnp:artist&gt;Samsung&lt;/upnp:artist&gt;&lt;upnp:albumArtURI&gt;http://192.168.0.6:57645/external/audio/albums/7.jpg&lt;/upnp:albumArtURI&gt;&lt;upnp:genre&gt;New Age&lt;/upnp:genre&gt;&lt;dc:date&gt;0&lt;/dc:date&gt;&lt;upnp:album&gt;Samsung&lt;/upnp:album&gt;&lt;upnp:originalTrackNumber&gt;0&lt;/upnp:originalTrackNumber&gt;&lt;res protocolInfo=&quot;http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_FLAGS=01700000000000000000000000000000&quot; bitrate=&quot;16000&quot; size=&quot;2705618&quot; duration=&quot;0:02:35.000&quot;&gt;http://192.168.0.6:57645/external/audio/media/23.mp3&lt;/res&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"></AVTransportURIMetaData>
</InstanceID>
</Event>
INFO  [2015-05-23 17:00:59.490307 | transport] RelativeTimePosition: 0:00:00
INFO  [2015-05-23 17:00:59.520221 | transport] TransportState: PLAYING
INFO  [2015-05-23 17:00:59.523910 | transport] CurrentTransportActions: PAUSE,STOP,SEEK
INFO  [2015-05-23 17:00:59.525540 | transport] CurrentTrackURI: http://192.168.0.6:57645/external/audio/media/23.mp3
INFO  [2015-05-23 17:00:59.526702 | transport] CurrentTrackMetaData: <DIDL-Lite xmlns="urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/" xmlns:upnp="urn:schemas-upnp-org:metadata-1-0/upnp/" xmlns:dc="http://purl.org/dc/elements/1.1/" xmlns:dlna="urn:schemas-dlna-org:metadata-1-0/" xmlns:sec="http://www.sec.co.kr/"><item id="/external/audio/media/23" parentID="/external/audio/media" restricted="1"><upnp:class>object.item.audioItem.musicTrack</upnp:class><dc:title>Over the horizon</dc:title><dc:creator>Samsung</dc:creator><upnp:artist>Samsung</upnp:artist><upnp:albumArtURI>http://192.168.0.6:57645/external/audio/albums/7.jpg</upnp:albumArtURI><upnp:genre>New Age</upnp:genre><dc:date>0</dc:date><upnp:album>Samsung</upnp:album><upnp:originalTrackNumber>0</upnp:originalTrackNumber><res protocolInfo="http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_FLAGS=01700000000000000000000000000000" bitrate="16000" size="2705618" duration="0:02:35.000">http://192.168.0.6:57645/external/audio/media/23.mp3</res></item></DIDL-Lite>
INFO  [2015-05-23 17:00:59.529438 | transport] LastChange: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<TransportState val="PLAYING"></TransportState>
<CurrentTransportActions val="PAUSE,STOP,SEEK"></CurrentTransportActions>
<CurrentTrackURI val="http://192.168.0.6:57645/external/audio/media/23.mp3"></CurrentTrackURI>
<CurrentTrackMetaData val="&lt;DIDL-Lite xmlns=&quot;urn:schemas-upnp-org:metadata-1-0/DIDL-Lite/&quot; xmlns:upnp=&quot;urn:schemas-upnp-org:metadata-1-0/upnp/&quot; xmlns:dc=&quot;http://purl.org/dc/elements/1.1/&quot; xmlns:dlna=&quot;urn:schemas-dlna-org:metadata-1-0/&quot; xmlns:sec=&quot;http://www.sec.co.kr/&quot;&gt;&lt;item id=&quot;/external/audio/media/23&quot; parentID=&quot;/external/audio/media&quot; restricted=&quot;1&quot;&gt;&lt;upnp:class&gt;object.item.audioItem.musicTrack&lt;/upnp:class&gt;&lt;dc:title&gt;Over the horizon&lt;/dc:title&gt;&lt;dc:creator&gt;Samsung&lt;/dc:creator&gt;&lt;upnp:artist&gt;Samsung&lt;/upnp:artist&gt;&lt;upnp:albumArtURI&gt;http://192.168.0.6:57645/external/audio/albums/7.jpg&lt;/upnp:albumArtURI&gt;&lt;upnp:genre&gt;New Age&lt;/upnp:genre&gt;&lt;dc:date&gt;0&lt;/dc:date&gt;&lt;upnp:album&gt;Samsung&lt;/upnp:album&gt;&lt;upnp:originalTrackNumber&gt;0&lt;/upnp:originalTrackNumber&gt;&lt;res protocolInfo=&quot;http-get:*:audio/mpeg:DLNA.ORG_PN=MP3;DLNA.ORG_OP=01;DLNA.ORG_FLAGS=01700000000000000000000000000000&quot; bitrate=&quot;16000&quot; size=&quot;2705618&quot; duration=&quot;0:02:35.000&quot;&gt;http://192.168.0.6:57645/external/audio/media/23.mp3&lt;/res&gt;&lt;/item&gt;&lt;/DIDL-Lite&gt;"></CurrentTrackMetaData>
</InstanceID>
</Event>
INFO  [2015-05-23 17:01:10.535852 | transport] CurrentTrackDuration: 0:02:35
INFO  [2015-05-23 17:01:10.537234 | transport] LastChange: <?xml version="1.0"?>
<Event xmlns="urn:schemas-upnp-org:metadata-1-0/AVT/">
<InstanceID val="0">
<CurrentTrackDuration val="0:02:35"></CurrentTrackDuration>
</InstanceID>
</Event>
INFO  [2015-05-23 17:01:11.542833 | transport] RelativeTimePosition: 0:00:01
INFO  [2015-05-23 17:01:12.548877 | transport] RelativeTimePosition: 0:00:02
INFO  [2015-05-23 17:01:13.555296 | transport] RelativeTimePosition: 0:00:03
INFO  [2015-05-23 17:01:14.560901 | transport] RelativeTimePosition: 0:00:04

Seeking (again, 11 seconds):

INFO  [2015-05-23 17:01:16.575461 | transport] RelativeTimePosition: 0:00:06
INFO  [2015-05-23 17:01:17.583182 | transport] RelativeTimePosition: 0:00:07
INFO  [2015-05-23 17:01:18.589508 | transport] RelativeTimePosition: 0:00:08
INFO  [2015-05-23 17:01:29.097301 | transport] RelativeTimePosition: 0:01:24
INFO  [2015-05-23 17:01:30.102974 | transport] RelativeTimePosition: 0:01:25
INFO  [2015-05-23 17:01:31.109281 | transport] RelativeTimePosition: 0:01:26

I've observed delays ranging from 10 seconds up to 30 or so. I think it may vary depending on the size of the file/codec/average bitrate, but I haven't been able to verify this.

Running the exact same version of gmrender-resurrect on a higher-powered x86_64 machine doesn't show any delays. RPi is at the latest firmware:

$ vcgencmd version
Apr 28 2015 18:50:58 
Copyright (c) 2012 Broadcom
version f33c3f25a8bdb3522ba6b47871e15897acc223da (clean) (release)

Playing the same tunes on the RPi using either mpd or mplayer doesn't result in any delays.

What could be the cause of this? I'm happy to dive into the source code and debug myself, if someone can give me a rough indicator to the likely areas to examine...

Many thanks, Adam

mr-smidge commented 9 years ago

Forgot to mention that I'm using gstreamer 1.2:

INFO  [2015-05-21 22:36:37.642524 | main] gmediarender 0.0.7-git log started [ gmediarender 2015-05-06_aa3d02c (libupnp-1.6.17; glib-2.40.0; gstreamer-1.2.0) ]
INFO  [2015-05-21 22:36:37.890607 | output] Using output module: gst (GStreamer multimedia framework)

.. and this is using Raspbian 7.

hzeller commented 8 years ago

Mmmh, that is strange. It sounds like there is some weird network latencies going on, but if you can play that via other means without trouble, then this might not be the reason. Do you get that same behavior independent of the server ? (because the way requesting sub-streams and the way they are buffered could be a problem).

Madhu205 commented 8 years ago

It Occurs with irrespective of servers.Whenever I use My PC as renderer,it works fine without any delay. CPU speeds of Raspberry and PC 700MHz and 1.80GHz.I am thinking it occurs due to processing speed.