Bugzilla – Bug 9482
sleep at end of song + transcoded stream => 100% CPU for slimserver.pl
Last modified: 2011-03-16 04:39:14 UTC
summary of the forum thread: Problem: after the player has been turned off by sleep mode, e.g. sleep at end of song, a few seconds later slimserver.pl consumes all available cpu, up to 100%. System: - with transcoding disabled it works fine - tested with two players, a transporter and a boom Description: 1. music plays 2. press "sleep" button to stop player at the end of the song 3. 10 seconds before the end of the current track, the next one is loaded (i.e flac/lame is started again) 4. the track ends, the player stops (screensaver off enabled) 5. a few seconds later slimserver.pl peaks at 100% CPU the server.log with player.source=info doesn't show anything unusual for me, at least nothing when 5. happens. log covers 3. to 4. (nothing is logged at 5.) [08-09-13 23:13:41.7564] Slim::Player::StreamingController::_nextTrackReady (618) 00:04:20:10:01:57: nextTrack will be index 21 [08-09-13 23:13:41.7568] Slim::Player::StreamingController::_Stream (857) 00:04:20:10:01:57: preparing to stream song index 21 [08-09-13 23:13:41.7571] Slim::Player::StreamingController::_Stream (862) Song queue is now 21,20 [08-09-13 23:13:41.7576] Slim::Player::Song::open (291) file:///data/common/All%20Music/Dido/No%20Angel/12%20-%20Take%20My%20Hand.mp3 [08-09-13 23:13:41.7582] Slim::Player::Song::open (307) URL is (no direct streaming) [file:///data/common/All%20Music/Dido/No%20Angel/12%20-%20Take%20My%20Hand.mp3] [08-09-13 23:13:41.7585] Slim::Player::ProtocolHandlers::openStream (81) Trying to open protocol stream for file:///data/common/All%20Music/Dido/No%20Angel/12%20-%20Take%20My%20Hand.mp3 [08-09-13 23:13:41.7588] Slim::Player::ProtocolHandlers::openStream (85) Found handler for file:///data/common/All%20Music/Dido/No%20Angel/12%20-%20Take%20My%20Hand.mp3 - using Slim::Player::Protocols::File [08-09-13 23:13:41.7595] Slim::Player::Protocols::File::open (79) duration: [402.756] size: [9790189] endian [] offset: [5010] for file:///data/common/All%20Music/Dido/No%20Angel/12%20-%20Take%20My%20Hand.mp3 [08-09-13 23:13:41.7598] Slim::Player::Protocols::File::open (96) Opening file /data/common/All Music/Dido/No Angel/12 - Take My Hand.mp3 [08-09-13 23:13:41.7604] Slim::Player::Protocols::File::open (161) Seeking in 5010 into /data/common/All Music/Dido/No Angel/12 - Take My Hand.mp3 [08-09-13 23:13:41.7608] Slim::Player::Song::open (323) URL is a song (audio): file:///data/common/All%20Music/Dido/No%20Angel/12%20-%20Take%20My%20Hand.mp3, type=mp3 [08-09-13 23:13:41.7632] Slim::Player::TranscodingHelper::getConvertCommand (316) Matched Format: mp3 Type: mp3 Command: [lame] --silent -q $QUALITY$ -v -B $BITRATE$ --mp3input $FILE$ - [08-09-13 23:13:41.7635] Slim::Player::Song::open (342) URL command [lame] --silent -q $QUALITY$ -v -B $BITRATE$ --mp3input $FILE$ - type mp3 format mp3 [08-09-13 23:13:41.7638] Slim::Player::Song::open (343) URL stream format : mp3 [08-09-13 23:13:41.7644] Slim::Player::Song::open (360) Tokenized command "/usr/bin/lame" --silent -q 3 -v -B 128 --mp3input "-" - [08-09-13 23:13:41.8041] Slim::Player::StreamingController::_Stream (899) 00:04:20:10:01:57: stream [08-09-13 23:13:41.8117] Slim::Player::Transporter::play (133) Setting DigitalInput to 0 for [file:///data/common/All%20Music/Dido/No%20Angel/12%20-%20Take%20My%20Hand.mp3] [08-09-13 23:13:41.8121] Slim::Player::Transporter::setDigitalInput (213) Switching to digital input 0 [08-09-13 23:13:41.8148] Slim::Player::StreamingController::_Stream (921) Song queue is now 21,20 [08-09-13 23:13:41.8153] Slim::Player::StreamingController::_setStreamingState (1686) new streaming state STREAMING [08-09-13 23:13:44.5362] Slim::Player::StreamingController::playerTrackStarted (1517) 00:04:20:10:01:57 [08-09-13 23:13:44.5366] Slim::Player::StreamingController::_setPlayingState (1677) new playing state PLAYING [08-09-13 23:13:44.5369] Slim::Player::StreamingController::_Playing (334) Song 20 is not longer in the queue [08-09-13 23:13:44.5373] Slim::Player::StreamingController::_Playing (340) Song 21 has now started playing [08-09-13 23:13:44.5389] Slim::Player::StreamingController::_Playing (367) Song queue is now 21 [08-09-13 23:13:54.5140] Slim::Player::StreamingController::_Stop (518) Song queue is now 21 [08-09-13 23:13:54.5146] Slim::Player::StreamingController::_setPlayingState (1677) new playing state STOPPED [08-09-13 23:13:54.5149] Slim::Player::StreamingController::_setStreamingState (1686) new streaming state IDLE [08-09-13 23:13:54.5160] Slim::Player::Source::playmode (173) 00:04:20:10:01:57: Current playmode: stop stracing slimserver.pl shows this pattern is repeated hundreds of times per second: gettimeofday({1221340490, 913722}, NULL) = 0 gettimeofday({1221340490, 913829}, NULL) = 0 gettimeofday({1221340490, 913936}, NULL) = 0 select(32, [6 8 9 10 12 14 15 17 18 20 21 22 26], [11 14], [11 14 15 17 18 20 21 22 24], {0, 25215}) = -1 EBADF (Bad file descriptor) gettimeofday({1221340490, 914173}, NULL) = 0 gettimeofday({1221340490, 914279}, NULL) = 0 gettimeofday({1221340490, 914386}, NULL) = 0 select(32, [6 8 9 10 12 14 15 17 18 20 21 22 26], [11 14], [11 14 15 17 18 20 21 22 24], {0, 24765}) = -1 EBADF (Bad file descriptor) gettimeofday({1221340490, 914628}, NULL) = 0 gettimeofday({1221340490, 914729}, NULL) = 0 gettimeofday({1221340490, 914838}, NULL) = 0 select(32, [6 8 9 10 12 14 15 17 18 20 21 22 26], [11 14], [11 14 15 17 18 20 21 22 24], {0, 24312}) = -1 EBADF (Bad file descriptor) kind regards, Markus
The problem is most easy to reproduce using "sleep at end of song". Since reporting this bug this happened twice while peforming normal operations like play, stop, next, add, ... although i don't know which specific action was responsible.
This is a duplicate of the problem being handled in bug 9473 *** This bug has been marked as a duplicate of bug 9473 ***
confirmed. problem is fixed. thanks!