volumio / Volumio2

Volumio 2 - Audiophile Music Player
http://volumio.org
Other
1.37k stars 315 forks source link

Youtube Streaming memory leak and 100% CPU #1556

Open SanKen opened 6 years ago

SanKen commented 6 years ago

I have problem with youtube stream. When playing sound is playback is not smooth. there is often something buffering. I do not know how to explain it.. But every stream is the same, it is not smooth. here is an additional sound. 40-60sec. the music does not stop. But this is annoying. Raspi PI 3B+ 2.389

Playing songs does not have this problem, only streaming.

SanKen commented 6 years ago

another issue When stream is playing. There is no information that whatever is playing.

SanKen commented 6 years ago

I updated volumio and now when playing stream CPU usage 100% by process /usr/local/bin/node /volumio/volumio.js and memory usage is 140MB-260MB Please help. volumio

xipmix commented 6 years ago

You'll need to post some logs for anyone to help effectively.

Does this happen with webradios, or just YT? It would help in reproducing the problem to give a couple of URLs for sources that you are having trouble with.

SanKen commented 6 years ago

ok, I will send a log. The problem is only stream on YT, webradio and youtube sound is working properly. link to example https://www.youtube.com/watch?v=dCP2r_LDYyc https://www.youtube.com/watch?v=5k_3qynHOwg

It looks like it is in any streaming.

logs http://logs.volumio.org/volumio/m5oqqmZ.html - when playing first yt stream

xipmix commented 6 years ago

I didn't realise you could actually stream YT videos - is that a third-party plugin? If so you might need to take this issue up with the author of the plugin.

Thanks for the log, had a quick look. Something is not quite right at startup

cze 03 22:17:23 volumio volumio[741]: info: Volumio called home
cze 03 22:17:23 volumio volumio[741]: info: Reloading queue from file
cze 03 22:17:23 volumio volumio[741]: info:
cze 03 22:17:23 volumio volumio[741]: info:  Error:  [50@0] {} No such directory
cze 03 22:17:23 volumio volumio[741]: at MpdClient.receive (/volumio/app/plugins/music_service/mpd/lib/mpd.js:63:14)
cze 03 22:17:23 volumio volumio[741]: at Socket. (/volumio/app/plugins/music_service/mpd/lib/mpd.js:43:10)
cze 03 22:17:23 volumio volumio[741]: at emitOne (events.js:96:13)
cze 03 22:17:23 volumio volumio[741]: at Socket.emit (events.js:188:7)
cze 03 22:17:23 volumio volumio[741]: at readableAddChunk (_stream_readable.js:176:18)
cze 03 22:17:23 volumio volumio[741]: at Socket.Readable.push (_stream_readable.js:134:10)
cze 03 22:17:23 volumio volumio[741]: at Pipe.onread (net.js:547:20)
cze 03 22:17:23 volumio volumio[741]: info: VolumeController:: Volume=undefined Mute =undefined

but I think it is likely a side issue, just wanted to note it here.

This looks like another side issue

cze 03 22:17:23 volumio volumio[741]: Error: Alsa Mixer Error: amixer: Invalid command!
cze 03 22:17:23 volumio volumio[741]: at Socket. (/volumio/app/volumecontrol.js:72:10)
cze 03 22:17:23 volumio volumio[741]: at emitOne (events.js:96:13)
cze 03 22:17:23 volumio volumio[741]: at Socket.emit (events.js:188:7)
cze 03 22:17:23 volumio volumio[741]: at readableAddChunk (_stream_readable.js:176:18)
cze 03 22:17:23 volumio volumio[741]: at Socket.Readable.push (_stream_readable.js:134:10)
cze 03 22:17:23 volumio volumio[741]: at Pipe.onread (net.js:547:20)

This is strange - lots of these entries - do you know what 'temp.sh' does? Can you turn it off (crontab -e)?

cze 03 22:32:01 volumio CRON[7017]: pam_unix(cron:session): session opened for user volumio by (uid=0)
cze 03 22:32:01 volumio CRON[7021]: (volumio) CMD (/bin/bash /home/volumio/temp.sh)
cze 03 22:32:01 volumio CRON[7017]: pam_unix(cron:session): session closed for user volumio

There seems to be a problem handling this webradio, see the traceback.

cze 04 11:39:09 volumio volumio[741]: ---------------------------- MPD announces system playlist update
cze 04 11:39:09 volumio volumio[741]: info: Ignoring MPD Status Update
cze 04 11:39:09 volumio volumio[741]: info: parsing response...
cze 04 11:39:09 volumio volumio[741]: info: parsing response...
cze 04 11:39:09 volumio volumio[741]: info: ControllerMpd::parseState
cze 04 11:39:09 volumio volumio[741]: info: ControllerMpd::sendMpdCommand playlistinfo
cze 04 11:39:09 volumio volumio[741]: info: ControllerMpd::sendMpdCommand load "http://listen.hardbase.fm/tunein-mp3-pls"
cze 04 11:39:09 volumio volumio[741]: info: sending command...
cze 04 11:39:09 volumio volumio[741]: info: sending command...
cze 04 11:39:09 volumio volumio[741]: info:
cze 04 11:39:09 volumio volumio[741]: info: ------------------------------ 11ms
cze 04 11:39:09 volumio volumio[741]: info: parsing response...
cze 04 11:39:09 volumio volumio[741]: info: ControllerMpd::parseTrackInfo
cze 04 11:39:09 volumio volumio[741]: info: ControllerMpd::pushError
cze 04 11:39:09 volumio volumio[741]: info:  TypeError: Cannot read property 'split' of undefined
cze 04 11:39:09 volumio volumio[741]: at Promise._successFn (/volumio/app/plugins/music_service/mpd/index.js:290:53)
cze 04 11:39:09 volumio volumio[741]: at nextTickCallback (/volumio/node_modules/kew/kew.js:47:28)
cze 04 11:39:09 volumio volumio[741]: at _combinedTickCallback (internal/process/next_tick.js:73:7)
cze 04 11:39:09 volumio volumio[741]: at process._tickCallback (internal/process/next_tick.js:104:9)

After you switch to a youtube source, I still see log entries related to hardbase.fm. I wonder if the switch from that queue item to the next (YT) is happening cleanly..

Have you tried with only one item in the queue, the YT source?

SanKen commented 6 years ago

This is not third-party plugin. Only volumio-youtube.

The problem occurs during the start Playing streaming.

yes, temp.sh is my script (cpu temperature), I can turn it off but this is small script.

hardbase.fm played before streaming, If you have any questions, please let me know. I saw a similar topic on the forum. https://volumio.org/forum/youtube-live-stream-radio-very-laggy-t9846.html - this is not my topic.

Maybe together we can fix it.

xipmix commented 6 years ago

Thanks for your reply, and explaining about temp.sh; I agree t it probably makes no difference to have it running

I found the plugin code. It looks like video playback was added in February but reverted a couple of months ago - it's unclear why... ah! here. So it would appear this is expected to work. with MPD doing the playback. So this may be 'fixed' already.

Can you open an issue in the volumio-plugins project, and cross-link to this? That should get the attention of the right people. I don't know if you can tell what version of the plugin you have - do you have /usr/local/bin/omxplayer on your system? Just to be clear that this is a different issue to the one in the forum - you see problems with all videos on YT, not just 'live streams' ?

I'm not sure what else can be done to progress this. It may be the Pi just doesn't have enough processing power. If you want to explore that a sensible test would be to try booting raspbian and trying to view a youtube video with the web browser provided there. Also, worth trying e.g. VLC playing a video file on the Pi or on a NAS in your home network.

SanKen commented 6 years ago

Ok, I wrote new issue as you asked.

I dont have the omxplayer.

There are no such problems while listening to music. The problem only occurs in listening music fron live stream.

I have the latest version of this plugin.

SanKen commented 6 years ago

It looks like something is wrong with volumio-youtube. After entering mpc status in ssh. It looks like every 1sec changes to a url. So if all the time removes and re-added this streaming .... When listening to regular music,(song from youtube) this address does not change. please check yourself

mpc status

I would stick the log, but I do not know if there is any information. But I see my ip there and maybe other data.

xipmix commented 6 years ago

If you want to do extra cleaning of your log, you can run volumio logdump and it will save it to local disk on the volumio system. It takes a little while. If you see things that need to be cleaned out but are not being cleaned out, please open an issue for that.

To capture the mpc status output you could try this

$ script mpcstatus.log
Script started, file is mpcstatus.log
$ for i in 0 1 2 3 4 5 6 7 8 9; do  mpc status; sleep 1; done
$ exit
Script done, file is mpstatus.log
$
SanKen commented 6 years ago

This is log when volumio playing youtube live from this link https://www.youtube.com/watch?v=dCP2r_LDYyc look [playing] #130/3600 0:00/0:00 (0%) WHY! logfromvolumio.txt

And second log is when playing this same song without volumio, only by mpc with youtube-dl (youtube-dl generates a link to me that adds to the queue.) mpcstatus.log

Do you see the difference?

xipmix commented 6 years ago

Not really sure what to make of this. Both logs show an index.m3u8 playlist file in the url, but the logfromvolumio shows an extra part to the url that looks like it might be a sequence of small seg.ts files (.ts is a video Transport Stream). Perhaps they break the video into small pieces to make it easier to deliver. Presumably youtube-dl is hiding all those messy details from you. @sla89, @crisp00 little help here?