301700 – Long slotAboutToFinish() delays cause repeat of tracks + wrong current track to be displayed (external mysql database)

Bug 301700 - Long slotAboutToFinish() delays cause repeat of tracks + wrong current track to be displayed (external mysql database)

Summary: Long slotAboutToFinish() delays cause repeat of tracks + wrong current track ...

Status:	RESOLVED FIXED

Alias:	None

Product:	amarok
Classification:	Applications
Component:	Playlists/Saved Playlists (show other bugs)
Version:	2.5.0
Platform:	Debian testing Linux

Importance:	NOR normal
Target Milestone:	2.6
Assignee:	Amarok Developers

URL:
Keywords:

Depends on:
Blocks:

Reported:	2012-06-12 02:24 UTC by Alan Ezust
Modified:	2012-07-14 08:59 UTC (History)
CC List:	2 users (show)

See Also:
Latest Commit:	http://commits.kde.org/amarok/cb3674aa81eeca4f85041eb77a42a33064362d59
Version Fixed In:	2.6
Sentry Crash Report:

Attachments
SqlPlaylist-don-t-observe-track-and-re-save-whole-pl.patch (4.13 KB, patch) 2012-06-12 22:59 UTC, Matěj Laitl	Details
View All Add an attachment

Note You need to log in before you can comment on or make changes to this bug.

Description Alan Ezust 2012-06-12 02:24:37 UTC

There is a long delay between tracks, or when I skip to another track, or when I edit a tag.
it appears that the playlist is being saved and the playlist is quite large. 


Reproducible: Always

Steps to Reproduce:
1. have an database with 13000 tracks, external mysql database
2. playlist with ~5000 tracks. random order.
3. long delays cause amarok to stop responding to events. 

I tried creating a new database with the same tracks/playlists and the problem went away for a week or so, and now I am starting to get delays that are long enough to cause the repeated track + wrong display issue again.

First of all, I am seeing the same problem now again in my newly created database, although not as often, and the delays are not as long yet. But it looks like the same thing is happening to my new database.

The output I see in stdout from debug mode may also help to indicate what it is doing. But first I'll paste the stack trace:

I did a ctrl-C during the "saving track with URL" output and saw this: 

Thread 1 (Thread 0x7ffff7f96780 (LWP 27028)):
#0  0x00007ffff483da0d in read () at ../sysdeps/unix/syscall-template.S:82
#1  0x00007fffd3820802 in vio_read_buff () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#2  0x00007fffd381281f in ?? () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#3  0x00007fffd381335c in my_net_read () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#4  0x00007fffd380cbb5 in cli_safe_read () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#5  0x00007fffd380dc08 in ?? () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#6  0x00007fffd380eaae in mysql_real_query () from /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18
#7  0x00007fffd3fc4dc2 in MySqlStorage::insert (this=0xfa8130, statement=...)
    at ../../../../../../../src/core-impl/collections/db/sql/mysql-shared/MySqlStorage.cpp:180
#8  0x00007ffff6ebf2c8 in Playlists::SqlPlaylist::saveTracks (this=this@entry=0x100bf40)
    at ../../src/playlistmanager/sql/SqlPlaylist.cpp:202
#9  0x00007ffff6ebfd7f in Playlists::SqlPlaylist::saveToDb (this=this@entry=0x100bf40, tracks=tracks@entry=true)
    at ../../src/playlistmanager/sql/SqlPlaylist.cpp:148
#10 0x00007ffff6ec0b25 in Playlists::SqlPlaylist::metadataChanged (this=0x100bf40, track=...)
    at ../../src/playlistmanager/sql/SqlPlaylist.cpp:289
#11 0x00007ffff75037d8 in Meta::Track::notifyObservers (this=0x2c04c20) at ../../../src/core/meta/Meta.cpp:324
---Type <return> to continue, or q <return> to quit---
#12 0x00007fffd3d84fe4 in SqlRegistry::commitDirtyTracks (this=0xfa5410)
    at ../../../../../../src/core-impl/collections/db/sql/SqlRegistry.cpp:789
#13 0x00007fffd3d96be1 in Meta::SqlTrack::commitMetaDataChanges (this=0x2c04c20)
    at ../../../../../../src/core-impl/collections/db/sql/SqlMeta.cpp:1028
#14 0x00007fffd3d98532 in Meta::SqlTrack::endMetaDataUpdate (this=0x2c04c20)
    at ../../../../../../src/core-impl/collections/db/sql/SqlMeta.cpp:786
#15 0x00007fffd3d8fa59 in Meta::SqlTrack::finishedPlaying (this=0x2c04c20, playedFraction=0.052830985915492956)
    at ../../../../../../src/core-impl/collections/db/sql/SqlMeta.cpp:1137
#16 0x00007ffff6f5c3ac in EngineController::play (this=0x945b40, track=..., offset=0) at ../../src/EngineController.cpp:410
#17 0x00007ffff6c1c489 in Playlist::Actions::play (this=this@entry=0x1058500, trackid=<optimized out>, now=now@entry=true)
    at ../../src/playlist/PlaylistActions.cpp:222
#18 0x00007ffff6c1cab3 in Playlist::Actions::requestUserNextTrack (this=this@entry=0x1058500)
    at ../../src/playlist/PlaylistActions.cpp:158
#19 0x00007ffff6c1cadf in Playlist::Actions::next (this=0x1058500) at ../../src/playlist/PlaylistActions.cpp:236
#20 0x00007ffff6ba1105 in Playlist::Actions::qt_static_metacall (_o=0x1058500, _c=16420080, _id=16384, _a=0xffffffffffffffff)
    at moc_PlaylistActions.cpp:81
#21 0x00007ffff51aa591 in QMetaObject::activate (sender=0x2b010c0, m=<optimized out>, local_signal_index=<optimized out>, 
    argv=0x7fffffff88d0) at kernel/qobject.cpp:3547
#22 0x00007ffff5bb5d52 in QAction::triggered (this=<optimized out>, _t1=false) at .moc/release-shared/moc_qaction.cpp:277
#23 0x00007ffff5bb5f3f in QAction::activate (this=0x2b010c0, event=<optimized out>) at kernel/qaction.cpp:1257
#24 0x00007ffff79e9ea0 in trigger (this=0x2b010c0) at /usr/include/qt4/QtGui/qaction.h:218
#25 KGlobalAccelPrivate::_k_invokeAction (this=<optimized out>, componentUnique=..., actionUnique=..., timestamp=372530492)
    at ../../kdeui/shortcuts/kglobalaccel.cpp:449
#26 0x00007ffff51aa591 in QMetaObject::activate (sender=0x29ed600, m=<optimized out>, local_signal_index=<optimized out>, 
---Type <return> to continue, or q <return> to quit---
    argv=0x7fffffff8ad0) at kernel/qobject.cpp:3547
#27 0x00007ffff7afa759 in OrgKdeKglobalaccelComponentInterface::globalShortcutPressed (this=<optimized out>, _t1=..., _t2=..., 
    _t3=372530492) at kglobalaccel_component_interface.moc:164
#28 0x00007ffff7afabc4 in OrgKdeKglobalaccelComponentInterface::qt_static_metacall (_o=0x29ed600, _id=<optimized out>, 
    _a=0x7fffffff8f20, _c=<optimized out>) at kglobalaccel_component_interface.moc:75
#29 0x00007ffff7afb37f in OrgKdeKglobalaccelComponentInterface::qt_metacall (this=0x29ed600, _c=QMetaObject::InvokeMetaMethod, 
    _id=0, _a=0x7fffffff8f20) at kglobalaccel_component_interface.moc:130

Is it saving the entire playlist between each track?

When it changes tracks, I see it spit out hundreds or perhaps thousands of messages like this:
 
amarok:   saving track with url  "amarok-sqltrackuid://26b5fc6050d5ae5c7ee3346914d5b886" 
amarok:   saving track with url  "amarok-sqltrackuid://b44c88e599a1818e98d948e3ef73d943" 
[ and it goes on like this for hundreds, perhaps thousands of tracks before I see this message:]
amarok:   saving track with url  "amarok-sqltrackuid://71033bc2eb7d5040063557b326f9874d" 
amarok:   saving track with url  "amarok-sqltrackuid://87bdd6277fc4be2e64619bc29284d449" 
After that I see the following output:

amarok:   BEGIN: void Playlist::Actions::requestNextTrack() 
amarok:     [Playlist::Actions] so far so good! 
amarok:     BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:     END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:     BEGIN: Playlist::ItemList* Playlist::NonlinearTrackNavigator::nextItemChooseDonorList() 
amarok:       BEGIN: virtual void Playlist::RandomTrackNavigator::planOne() 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:       END__: virtual void Playlist::RandomTrackNavigator::planOne() [Took: 0s] 
amarok:     END__: Playlist::ItemList* Playlist::NonlinearTrackNavigator::nextItemChooseDonorList() [Took: 0s] 
amarok:     BEGIN: virtual void Playlist::NonlinearTrackNavigator::setCurrentItem(quint64, bool) 
amarok:       BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:       END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:     END__: virtual void Playlist::NonlinearTrackNavigator::setCurrentItem(quint64, bool) [Took: 0s] 
amarok:     BEGIN: void Playlist::Actions::play(quint64, bool) 
amarok:       BEGIN: void EngineController::setNextTrack(Meta::TrackPtr) 
amarok:         [EngineController] locking mutex 
amarok:         [EngineController] locked! 
amarok:       END__: void EngineController::setNextTrack(Meta::TrackPtr) [Took: 0.017s] 
amarok:     END__: void Playlist::Actions::play(quint64, bool) [Took: 0.017s] 
amarok:   END__: void Playlist::Actions::requestNextTrack() [Took: 0.018s] 
amarok: END__: void EngineController::slotAboutToFinish() [DELAY Took (quite long) 24s] 
Got next source. Waiting for end of current. 
New source:  QUrl( "file:///mnt/music/ByGenre/WorldAmbient/Hammock/hammock-kenotic-09-glacial.mp3" )  
Transitioning to state "ready" 
State change 
Moving from "playing" 2 to "paused" 4 
[Thread 0x7fffc0f24700 (LWP 27063) exited]
State change 
Moving from "paused" 4 to "ready" 1 
Transitioning to state "playing" 
amarok: BEGIN: void ScanManager::checkForDirectoryChanges() 
amarok:   BEGIN: void DirWatchJob::setPaused(bool) 
amarok:   END__: void DirWatchJob::setPaused(bool) [Took: 0s] 
amarok: END__: void ScanManager::checkForDirectoryChanges() [Took: 0s] 
Stream changed to file:///mnt/music/ByGenre/TechnoTripHop/Twilight%20Circus/Dub%20Voyage/02%20-%20Dub%20Voyage%20-%20Twilight%20Circus.mp3 
[New Thread 0x7fffc0f24700 (LWP 27068)]
State change 
[New Thread 0x7fffbbfff700 (LWP 27069)]
Stream changed to file:///mnt/music/ByGenre/TechnoTripHop/Twilight%20Circus/Dub%20Voyage/02%20-%20Dub%20Voyage%20-%20Twilight%20Circus.mp3 
Duration message 
State change 
[Thread 0x7fffbbfff700 (LWP 27069) exited]
amarok: BEGIN: void EngineController::slotStateChanged(Phonon::State, Phonon::State) 
amarok: END__: void EngineController::slotStateChanged(Phonon::State, Phonon::State) [Took: 0s] 
amarok: BEGIN: void EngineController::slotTrackLengthChanged(qint64) 
amarok:   BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:     found  0  timecodes on this track 
amarok:   END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0s] 
amarok: END__: void EngineController::slotTrackLengthChanged(qint64) [Took: 0s] 
amarok: BEGIN: void EngineController::slotStateChanged(Phonon::State, Phonon::State) 
amarok: END__: void EngineController::slotStateChanged(Phonon::State, Phonon::State) [Took: 0s] 
Moving from "ready" 1 to "paused" 4 
Moving from "paused" 4 to "playing" 2 
amarok: BEGIN: void EngineController::slotMetaDataChanged() 
amarok:   [EngineController] Artist     :  ("Twilight Circus") 
amarok:   [EngineController] Album      :  ("Dub Voyage") 
amarok:   [EngineController] Title      :  ("Dub Voyage") 
amarok:   [EngineController] Genre      :  ("Dub") 
amarok:   [EngineController] Tracknumber:  () 
amarok:   [EngineController] Length     :  () 
amarok:   [EngineController] Track changed:  false current: 0x351b310 url "file:///mnt/music/ByGenre/WorldAmbient/Hammock/hammock-kenotic-09-glacial.mp3" 
amarok:   [EngineController] no spam 
amarok:   BEGIN: void MetaStream::Track::Private::currentMetadataChanged(QVariantMap) 
amarok:   END__: void MetaStream::Track::Private::currentMetadataChanged(QVariantMap) [Took: 0s] 
amarok: END__: void EngineController::slotMetaDataChanged() [Took: 0s] 
amarok: BEGIN: void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&) 
amarok:   BEGIN: void Context::ContextView::slotTrackChanged(Meta::TrackPtr) 
amarok:   END__: void Context::ContextView::slotTrackChanged(Meta::TrackPtr) [Took: 0s] 
amarok:   Playlist properties changed; can go next: true ; can go previous: true 
amarok:   BEGIN: void Amarok::Mpris2DBusHandler::updateTrackProperties() 
QString::arg: Argument missing: /PendingTrack, /org/mpris/MediaPlayer2
amarok:   END__: void Amarok::Mpris2DBusHandler::updateTrackProperties() [Took: 0s] 
amarok:   BEGIN: void Playlist::Actions::slotTrackPlaying(Meta::TrackPtr) 
amarok:     BEGIN: void PlaylistInfoWidget::updateTotalPlaylistLength() 
amarok:     END__: void PlaylistInfoWidget::updateTotalPlaylistLength() [Took: 0.002s] 
amarok:     BEGIN: void Playlist::NonlinearTrackNavigator::slotActiveTrackChanged(quint64) 
amarok:       BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:       END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:       BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:       END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:     END__: void Playlist::NonlinearTrackNavigator::slotActiveTrackChanged(quint64) [Took: 0s] 
amarok:     Active track changed; can go next: true ; can go previous: true 
amarok:     BEGIN: void Playlist::PrettyListView::slotPlaylistActiveTrackChanged() 
amarok:       BEGIN: void Playlist::PrettyListView::scrollToActiveTrack() 
amarok:       END__: void Playlist::PrettyListView::scrollToActiveTrack() [Took: 0.021s] 
amarok:     END__: void Playlist::PrettyListView::slotPlaylistActiveTrackChanged() [Took: 0.021s] 
amarok:   END__: void Playlist::Actions::slotTrackPlaying(Meta::TrackPtr) [Took: 0.026s] 
amarok:   BEGIN: void TimecodeObserver::trackPlaying(Meta::TrackPtr) 
amarok:     current track name:  "Glacial" 
amarok:     Track timecodeable 
amarok:   END__: void TimecodeObserver::trackPlaying(Meta::TrackPtr) [Took: 0s] 
amarok:   BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:     found  0  timecodes on this track 
amarok:   END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0.001s] 
amarok:   BEGIN: void OSDWidget::show(const QString&, const QImage&) 
amarok:   END__: void OSDWidget::show(const QString&, const QImage&) [Took: 0s] 
amarok: END__: void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&) [Took: 0.14s] 
amarok: BEGIN: void EngineController::slotStateChanged(Phonon::State, Phonon::State) 
amarok: END__: void EngineController::slotStateChanged(Phonon::State, Phonon::State) [Took: 0s] 
amarok: BEGIN: void EngineController::slotMetaDataChanged() 
amarok:   [EngineController] Artist     :  ("Twilight Circus") 
amarok:   [EngineController] Album      :  ("Dub Voyage") 
amarok:   [EngineController] Title      :  ("Dub Voyage") 
amarok:   [EngineController] Genre      :  ("Dub") 
amarok:   [EngineController] Tracknumber:  () 
amarok:   [EngineController] Length     :  () 
amarok:   [EngineController] Track changed:  true current: 0x2e34130 url "file:///mnt/music/ByGenre/WorldAmbient/Hammock/hammock-kenotic-09-glacial.mp3" 
amarok: END__: void EngineController::slotMetaDataChanged() [Took: 0s] 
amarok: BEGIN: void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&) 
amarok:   BEGIN: void Context::ContextView::slotTrackChanged(Meta::TrackPtr) 
amarok:   END__: void Context::ContextView::slotTrackChanged(Meta::TrackPtr) [Took: 0s] 
amarok:   Playlist properties changed; can go next: true ; can go previous: true 
amarok:   BEGIN: void Amarok::Mpris2DBusHandler::updateTrackProperties() 
amarok:   END__: void Amarok::Mpris2DBusHandler::updateTrackProperties() [Took: 0s] 
amarok:   BEGIN: void Playlist::Actions::slotTrackPlaying(Meta::TrackPtr) 
amarok:     [WARNING] [Playlist::Actions] engineNewTrackPlaying: "Glacial" does not match what the playlist controller thought it should be 
amarok:   END__: void Playlist::Actions::slotTrackPlaying(Meta::TrackPtr) [Took: 0s] 
amarok:   BEGIN: void TimecodeObserver::trackPlaying(Meta::TrackPtr) 
amarok:   END__: void TimecodeObserver::trackPlaying(Meta::TrackPtr) [Took: 0s] 
amarok:   BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:     found  0  timecodes on this track 
amarok:   END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0s] 
amarok:   BEGIN: void OSDWidget::show(const QString&, const QImage&) 
amarok:   END__: void OSDWidget::show(const QString&, const QImage&) [Took: 0s] 
amarok: END__: void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&) [Took: 0.004s] 
amarok: BEGIN: void EngineController::slotTrackLengthChanged(qint64) 
amarok:   BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:     found  0  timecodes on this track 
amarok:   END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0s] 
amarok: END__: void EngineController::slotTrackLengthChanged(qint64) [Took: 0s] 
amarok: BEGIN: void EngineController::slotTrackLengthChanged(qint64) 
amarok:   BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:     found  0  timecodes on this track 
amarok:   END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0s] 
amarok: END__: void EngineController::slotTrackLengthChanged(qint64) [Took: 0s] 
amarok: BEGIN: void EngineController::slotStateChanged(Phonon::State, Phonon::State) 
amarok: END__: void EngineController::slotStateChanged(Phonon::State, Phonon::State) [Took: 0s] 
^Aamarok: BEGIN: void ScanManager::checkForDirectoryChanges() 
amarok:   BEGIN: void DirWatchJob::setPaused(bool) 
amarok:   END__: void DirWatchJob::setPaused(bool) [Took: 0s] 
amarok: END__: void ScanManager::checkForDirectoryChanges() [Took: 0s] 
^


Tried to continue but the process was gone. Ran it again, captured some more output
arok:   saving track with url  "amarok-sqltrackuid://09aa3b3b74063a251a042f67f1ceb09e" 
amarok:   saving track with url  "amarok-sqltrackuid://0aa54d3d1066e891e83af4dd41708f43" 
amarok:   saving track with url  "amarok-sqltrackuid://7695ceeaeab1d24e347ed536202795f6" 
amarok:   saving track with url  "amarok-sqltrackuid://224154d93fcc3f0f4b8227e043af0356" 
amarok:   saving track with url  "amarok-sqltrackuid://0df9c690cffae0dfd1f6680f68d1acb3" 
amarok:   saving track with url  "amarok-sqltrackuid://82a298b251bb33c44b8769239d866745" 
amarok:   saving track with url  "amarok-sqltrackuid://e1093e86d0a32ac5ca6200a62d7fbef4" 
amarok:   saving track with url  "amarok-sqltrackuid://6f79c5e406676d859def43bf30eab296" 
amarok:   saving track with url  "amarok-sqltrackuid://9a4e01051ebe545f3e3965f0fafad616" 
amarok:   saving track with url  "amarok-sqltrackuid://8443a15023a9e9ebf77bf6f558621d73" 
amarok:   saving track with url  "amarok-sqltrackuid://311241d748fdef9b15c05bea15f3941d" 
amarok:   saving track with url  "amarok-sqltrackuid://e3a27574dad7273e60d070fd8199745a" 
amarok:   saving track with url  "amarok-sqltrackuid://71033bc2eb7d5040063557b326f9874d" 
amarok:   saving track with url  "amarok-sqltrackuid://87bdd6277fc4be2e64619bc29284d449" 
amarok:   BEGIN: void Playlist::Actions::requestNextTrack() 
amarok:     [Playlist::Actions] so far so good! 
amarok:     BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:     END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:     BEGIN: Playlist::ItemList* Playlist::NonlinearTrackNavigator::nextItemChooseDonorList() 
amarok:       BEGIN: virtual void Playlist::RandomTrackNavigator::planOne() 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:         END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:       END__: virtual void Playlist::RandomTrackNavigator::planOne() [Took: 0s] 
amarok:     END__: Playlist::ItemList* Playlist::NonlinearTrackNavigator::nextItemChooseDonorList() [Took: 0s] 
amarok:     BEGIN: virtual void Playlist::NonlinearTrackNavigator::setCurrentItem(quint64, bool) 
amarok:       BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:       END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:     END__: virtual void Playlist::NonlinearTrackNavigator::setCurrentItem(quint64, bool) [Took: 0s] 
amarok:     BEGIN: void Playlist::Actions::play(quint64, bool) 
amarok:       BEGIN: void EngineController::setNextTrack(Meta::TrackPtr) 
amarok:         [EngineController] locking mutex 
amarok:         [EngineController] locked! 
amarok:       END__: void EngineController::setNextTrack(Meta::TrackPtr) [Took: 0s] 
amarok:     END__: void Playlist::Actions::play(quint64, bool) [Took: 0s] 
amarok:   END__: void Playlist::Actions::requestNextTrack() [Took: 0s] 
amarok: END__: void EngineController::slotAboutToFinish() [DELAY Took (quite long) 21s] 
Got next source. Waiting for end of current. 
New source:  QUrl( "file:///mnt/music/ByGenre/4ADSoundtrack/Twelfth Of Never/Things That Were/01 - Twelfth of Never - Octoberland.mp3" )  
Transitioning to state "ready" 
State change 
Moving from "playing" 2 to "paused" 4 
[Thread 0x7fffc1956700 (LWP 27141) exited]
State change 
Moving from "paused" 4 to "ready" 1 
Transitioning to state "playing" 
amarok: BEGIN: void ScanManager::checkForDirectoryChanges() 
amarok:   BEGIN: virtual void ScanManager::requestIncrementalScan(const QString&) 
amarok:     [ScanManager] addDirToList for "" 
[New Thread 0x7fffc1956700 (LWP 27147)]
amarok:     BEGIN: virtual void ScannerJob::run() 
amarok:       [MySqlStorage] Initialized thread, count== 4 
amarok:     END__: virtual void ScanManager::requestIncrementalScan(const QString&) [Took: 0.001s] 
amarok:     BEGIN: DirWatchJob::DirWatchJob(QObject*, Collections::DatabaseCollection*) 
amarok:     END__: DirWatchJob::DirWatchJob(QObject*, Collections::DatabaseCollection*) [Took: 0s] 
amarok:   END__: void ScanManager::checkForDirectoryChanges() [Took: 0.001s] 
amarok:   BEGIN: virtual void DirWatchJob::run() 
Stream changed to file:///mnt/music/ByGenre/WorldAmbient/Rena%20Jones/indra%27s%20web/08%20-%20A%23m%20-%20The%20Webs%20We%20Weave%20-%20Rena%20Jones.mp3 
[New Thread 0x7fffc1155700 (LWP 27149)]
State change 
[New Thread 0x7fffc0854700 (LWP 27151)]
Stream changed to file:///mnt/music/ByGenre/WorldAmbient/Rena%20Jones/indra%27s%20web/08%20-%20A%23m%20-%20The%20Webs%20We%20Weave%20-%20Rena%20Jones.mp3 
State change 
Duration message 
[Thread 0x7fffc0854700 (LWP 27151) exited]
amarok:     BEGIN: void EngineController::slotStateChanged(Phonon::State, Phonon::State) 
amarok:     END__: void EngineController::slotStateChanged(Phonon::State, Phonon::State) [Took: 0.001s] 
amarok:     BEGIN: void EngineController::slotTrackLengthChanged(qint64) 
amarok:       BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:         found  0  timecodes on this track 
amarok:       END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0s] 
amarok:     END__: void EngineController::slotTrackLengthChanged(qint64) [Took: 0s] 
amarok:     BEGIN: void EngineController::slotStateChanged(Phonon::State, Phonon::State) 
amarok:     END__: void EngineController::slotStateChanged(Phonon::State, Phonon::State) [Took: 0s] 
Moving from "ready" 1 to "paused" 4 
Moving from "paused" 4 to "playing" 2 
amarok:     BEGIN: void EngineController::slotMetaDataChanged() 
amarok:       [EngineController] Artist     :  ("Rena Jones") 
amarok:       [EngineController] Album      :  ("Indra's Web") 
amarok:       [EngineController] Title      :  ("A#m - The Webs We Weave") 
amarok:       [EngineController] Genre      :  ("Chill") 
amarok:       [EngineController] Tracknumber:  () 
amarok:       [EngineController] Length     :  () 
amarok:       [EngineController] Track changed:  false current: 0x31462a0 url "file:///mnt/music/ByGenre/4ADSoundtrack/Twelfth Of Never/Things That Were/01 - Twelfth of Never - Octoberland.mp3" 
amarok:       [EngineController] no spam 
amarok:       BEGIN: void MetaStream::Track::Private::currentMetadataChanged(QVariantMap) 
amarok:       END__: void MetaStream::Track::Private::currentMetadataChanged(QVariantMap) [Took: 0s] 
amarok:     END__: void EngineController::slotMetaDataChanged() [Took: 0s] 
amarok:     BEGIN: void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&) 
amarok:       BEGIN: void Context::ContextView::slotTrackChanged(Meta::TrackPtr) 
amarok:       END__: void Context::ContextView::slotTrackChanged(Meta::TrackPtr) [Took: 0s] 
amarok:       Playlist properties changed; can go next: true ; can go previous: true 
amarok:       BEGIN: void Amarok::Mpris2DBusHandler::updateTrackProperties() 
QString::arg: Argument missing: /PendingTrack, /org/mpris/MediaPlayer2
amarok:       END__: void Amarok::Mpris2DBusHandler::updateTrackProperties() [Took: 0s] 
amarok:       BEGIN: void Playlist::Actions::slotTrackPlaying(Meta::TrackPtr) 
amarok:         BEGIN: void PlaylistInfoWidget::updateTotalPlaylistLength() 
amarok:         END__: void PlaylistInfoWidget::updateTotalPlaylistLength() [Took: 0.002s] 
amarok:         BEGIN: void Playlist::NonlinearTrackNavigator::slotActiveTrackChanged(quint64) 
amarok:           BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:           END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:           BEGIN: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() 
amarok:           END__: void Playlist::NonlinearTrackNavigator::doItemListsMaintenance() [Took: 0s] 
amarok:         END__: void Playlist::NonlinearTrackNavigator::slotActiveTrackChanged(quint64) [Took: 0s] 
amarok:         Active track changed; can go next: true ; can go previous: true 
amarok:         BEGIN: void Playlist::PrettyListView::slotPlaylistActiveTrackChanged() 
amarok:           BEGIN: void Playlist::PrettyListView::scrollToActiveTrack() 
amarok:           END__: void Playlist::PrettyListView::scrollToActiveTrack() [Took: 0.023s] 
amarok:         END__: void Playlist::PrettyListView::slotPlaylistActiveTrackChanged() [Took: 0.023s] 
amarok:       END__: void Playlist::Actions::slotTrackPlaying(Meta::TrackPtr) [Took: 0.028s] 
amarok:       BEGIN: void TimecodeObserver::trackPlaying(Meta::TrackPtr) 
amarok:         current track name:  "Octoberland" 
amarok:         Track timecodeable 
amarok:       END__: void TimecodeObserver::trackPlaying(Meta::TrackPtr) [Took: 0s] 
amarok:       BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:         found  0  timecodes on this track 
amarok:       END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0.002s] 
amarok:     END__: virtual void DirWatchJob::run() [Took: 1.2s] 
amarok:     [ScanManager] ScannerJob: got count: 2526 
amarok:     BEGIN: void OSDWidget::show(const QString&, const QImage&) 
amarok:     END__: void OSDWidget::show(const QString&, const QImage&) [Took: 0s] 
amarok:   END__: void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&) [Took: 0.4s] 
amarok:   BEGIN: void EngineController::slotStateChanged(Phonon::State, Phonon::State) 
amarok:   END__: void EngineController::slotStateChanged(Phonon::State, Phonon::State) [Took: 0s] 
amarok:   BEGIN: void EngineController::slotMetaDataChanged() 
amarok:     [EngineController] Artist     :  ("Rena Jones") 
amarok:     [EngineController] Album      :  ("Indra's Web") 
amarok:     [EngineController] Title      :  ("A#m - The Webs We Weave") 
amarok:     [EngineController] Genre      :  ("Chill") 
amarok:     [EngineController] Tracknumber:  () 
amarok:     [EngineController] Length     :  () 
amarok:     [EngineController] Track changed:  true current: 0x33ce690 url "file:///mnt/music/ByGenre/4ADSoundtrack/Twelfth Of Never/Things That Were/01 - Twelfth of Never - Octoberland.mp3" 
amarok:   END__: void EngineController::slotMetaDataChanged() [Took: 0s] 
amarok:   BEGIN: void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&) 
amarok:     BEGIN: void Context::ContextView::slotTrackChanged(Meta::TrackPtr) 
amarok:     END__: void Context::ContextView::slotTrackChanged(Meta::TrackPtr) [Took: 0s] 
amarok:     Playlist properties changed; can go next: true ; can go previous: true 
amarok:     BEGIN: void Amarok::Mpris2DBusHandler::updateTrackProperties() 
amarok:     END__: void Amarok::Mpris2DBusHandler::updateTrackProperties() [Took: 0s] 
amarok:     BEGIN: void Playlist::Actions::slotTrackPlaying(Meta::TrackPtr) 
amarok:       [WARNING] [Playlist::Actions] engineNewTrackPlaying: "Octoberland" does not match what the playlist controller thought it should be 
amarok:     END__: void Playlist::Actions::slotTrackPlaying(Meta::TrackPtr) [Took: 0s] 
amarok:     BEGIN: void TimecodeObserver::trackPlaying(Meta::TrackPtr) 
amarok:     END__: void TimecodeObserver::trackPlaying(Meta::TrackPtr) [Took: 0s] 
amarok:     BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:       found  0  timecodes on this track 
amarok:     END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0s] 
amarok:     BEGIN: void OSDWidget::show(const QString&, const QImage&) 
amarok:     END__: void OSDWidget::show(const QString&, const QImage&) [Took: 0s] 
amarok:   END__: void EngineController::slotNewTrackPlaying(const Phonon::MediaSource&) [Took: 0.004s] 
amarok:   BEGIN: void EngineController::slotTrackLengthChanged(qint64) 
amarok:     BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:       found  0  timecodes on this track 
amarok:     END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0s] 
amarok:   END__: void EngineController::slotTrackLengthChanged(qint64) [Took: 0s] 
amarok:   BEGIN: void EngineController::slotStateChanged(Phonon::State, Phonon::State) 
amarok:   END__: void EngineController::slotStateChanged(Phonon::State, Phonon::State) [Took: 0s] 
amarok:   BEGIN: void EngineController::slotTrackLengthChanged(qint64) 
amarok:     BEGIN: void ProgressWidget::redrawBookmarks(const QString*) 
amarok:       found  0  timecodes on this track 
amarok:     END__: void ProgressWidget::redrawBookmarks(const QString*) [Took: 0s] 
amarok:   END__: void EngineController::slotTrackLengthChanged(qint64) [Took: 0s] 
amarok:   BEGIN: virtual void SqlScanResultProcessor::commit() 
amarok:   END__: virtual void SqlScanResultProcessor::commit() [DELAY Took (quite long) 14s] 
amarok:   [ScanManager] ScannerJob finished 
amarok: END__: virtual void ScannerJob::run() [DELAY Took (quite long) 15s] 
amarok: BEGIN: virtual ScannerJob::~ScannerJob() 
amarok: END__: virtual ScannerJob::~ScannerJob() [Took: 0s] 



Actual Results:  
after a track is over, a long pause of silence, followed by the same track repeated and it displaying something else as my current playing track. 

Expected Results:  
being able to see what track I am hearing. 

I did import my own ratings data into the 'statistics' table using a program that is not amarok because I can't figure out how to do it with amarok.

Comment 1 Alan Ezust 2012-06-12 02:55:51 UTC

I just counted the number of lines of output that I clipped from the output above.
Each line looked like this:
amarok:       saving track with url  "amarok-sqltrackuid://2de48345e20824101da573bfc850f226"
There are over 16,000 of these lines!
Which happens to be the number of rows in my urls and statistics tables.

Comment 2 Myriam Schweingruber 2012-06-12 07:13:30 UTC

Where is your external database located, on a remote share? How do you access this?

Comment 3 Alan Ezust 2012-06-12 14:56:49 UTC

via TCP, i access mysql via localhost. The drive is mounted locally.

Comment 4 Alan Ezust 2012-06-12 15:08:05 UTC

Adding a dummy comment so I can get rid of "needsinfo" status.

Comment 5 Matěj Laitl 2012-06-12 22:59:56 UTC

Created attachment 71779 [details]
SqlPlaylist-don-t-observe-track-and-re-save-whole-pl.patch

Alan, please apply this patch atop of the current Amarok git master and report whether it fixes the problem for you. Good guide to compiling Amarok is at http://blogs.fsfe.org/myriam/archives/87

Comment 6 Matěj Laitl 2012-06-12 23:01:20 UTC

Waiting for reporter.

Comment 7 Alan Ezust 2012-06-13 13:00:13 UTC

I can't reproduce my original issue with the current amarok GIT trunk (so in other words, ahhh, much better!), but I am testing both that and the patched version to see if I can notice any performance difference.  I will post more info when I have it.

Comment 8 Alan Ezust 2012-06-13 18:41:44 UTC

ok, the patched version definitely works better for me than the unpatched one. 
I tried running the latest unpatched git against my newer database, it upgraded the DB, hung, and when I re-ran it, I am seeing infinite saving track with url: lines and it is just stuck.

So it seems the patch  does resolve my issue!

Comment 9 Bart Cerneels 2012-06-14 12:04:23 UTC

I would sign of on that patch, there is little benefit to live updates of playlists. On save is enough.

Comment 10 Matěj Laitl 2012-06-14 12:50:35 UTC

(In reply to comment #9)
> I would sign of on that patch, there is little benefit to live updates of
> playlists. On save is enough.

I agree, but we don't currently save playlists on Amarok close, do we? In case not, the playlist entries can become stale when url of the track changes while Amarok is running.

Another alternative would be to store uidUrl() that shouldn't change, but that would require extending CollectionManager and Collections to add trackForUidUrl().

Yet another alternative would be to update just relevant tracks from SqlPlaylist::metadataChanged().

Comment 11 Matěj Laitl 2012-07-14 08:59:42 UTC

Git commit cb3674aa81eeca4f85041eb77a42a33064362d59 by Matěj Laitl.
Committed on 13/06/2012 at 00:52.
Pushed by laitl into branch 'master'.

SqlPlaylist: don't observe track and re-save whole playlist on track change

No other playlist does that and this causes problems when someone has
really big playlists and slow connection to external MySQL db.

Not updating track metadata should not hurt, these are immediately
replaced by real ones by MetaProxy::Track. Moreover for uidUrl updates
there is SqlTrack::updatePlaylistsToDb() (I don't however know whether
it works as expected). Acked by Bart on the bug.
FIXED-IN: 2.6

M  +1    -0    ChangeLog
M  +0    -24   src/playlistmanager/sql/SqlPlaylist.cpp
M  +1    -9    src/playlistmanager/sql/SqlPlaylist.h

http://commits.kde.org/amarok/cb3674aa81eeca4f85041eb77a42a33064362d59