Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[dpetr]

As this log illustrates, shutting down MC 13.0.108 takes an inordinate amount of time.  DB has around 5500 records, all audio.  Nothing out of the ordinary I think.
System 64 bit Vista.  Otherwise, everything is fine.  Smaller DB (< 100 records seems OK).  Rebuilt DB several times, same result. 

Note, slowdown only occurs when closing MC while something is playing.

Note the elapsed time shutting down CMCTools Core.

0041171: 4584: General: CMCToolsCore::StopTools: Destroying handheld engine
0041171: 4584: General: CMCToolsCore::StopTools: Destroying podcasting
0041187: 4584: General: CMCToolsCore::StopTools: Stopping scheduler
0041187: 4584: General: CMCToolsCore::StopTools: Destroying TV guide scanner
0041203: 4584: General: CMCToolsCore::StopTools: Stopping TV recording
0041203: 4584: General: CMCToolsCore::StopTools: Unloading hotkeys
0041218: 4584: General: CMCToolsCore::StopTools: Cancelling downloads
0041218: 4584: General: CDownloadQueue::Cancel: Start
0041234: 4584: General: CDownloadQueue::Cancel: ID=-1
0041234: 4584: General: CDownloadQueue::Cancel: elapsed time before cancel loop = 15
0041250: 4584: General: CDownloadQueue::Cancel: elapsed time for cancel loop = 11
0041250: 4584: General: CDownloadQueue::Cancel: elapsed time for RemoveDeadTasks = 0
0041250: 4584: General: CDownloadQueue::Cancel: Finish (32 ms)
0041250: 4584: General: CMCToolsCore::StopTools: Saving MRU information
0041265: 4584: General: CMCToolsCore::StopTools: Finish (10156 ms)

[Matt]

Could you post more of the log?  The statement showing what is slow is above what was posted.

Thanks.

[dpetr]

Here's the log from the start of the close action.  I see nothing approaching 10 seconds before the close action.

0022500: 4584: Playback: CJRPlaybackEngine::Play: Start
0022515: 4584: Playback: CJRPlaybackEngine::Play: Playing: D:\Music\Opera_4\History of Opera\Vol 05\06 - L'elisir D'amore, Nemorino's aria.mp3
0022515: 4584: Playback: CJRPlaybackEngine::Play: Filetype: mp3; Type: 1; Can play: 1; Playback object: 0x60bc548
0022531: 4584: Playback: CJRPlaybackEngine::StartPlayFile: Start
0022531: 4584: Playback: CMJPlaybackType::Play: Start
0022625: 4584: Playback: CMJPlayerCore::Play: Start
0022765: 4584: Playback: CMJPlayerCore::Play: Created feeder helper for type mp3 (native: 1)
0022781: 4584: Playback: CMJWaveFeeder::Play: Start
0022796: 4584: Playback: CMJWaveFeeder::Play: Finish (15 ms)
0022796: 4772: Playback: CMJWaveFeeder::Thread: Start
0022812: 4772: Playback: CMJWaveFeeder::Thread: Adding skinning
0022812: 4584: Playback: CMJPlayerCore::Play: Play succeeded
0022828: 4584: Playback: CMJPlayerCore::Play: Result: 1
0022843: 4772: Playback: CMJWaveFeeder::Thread: Opening file
0022859: 4584: Playback: CMJPlayerCore::Play: Finish (234 ms)
0022859: 4772: Reader: CLocalReader::OpenInternal: Opening: D:\Music\Opera_4\History of Opera\Vol 05\06 - L'elisir D'amore, Nemorino's aria.mp3
0022890: 4584: Playback: CMJPlaybackType::Play: Play result: 1
0022906: 4584: Playback: CMJPlaybackType::Play: Finish (375 ms)
0022906: 4584: Playback: CJRPlaybackEngine::StartPlayFile: Play returned: 1
0022906: 4584: Playback: CJRPlaybackEngine::StartPlayFile: Finish (375 ms)
0022906: 4584: Playback: CJRPlaybackEngine::Play: StartPlayFile returned 1
0022921: 4772: Playback: CMJWaveFeeder::Thread: Setting output format
0022953: 4772: Playback: CPlayerZone::OnNewStream: Start
0022953: 4584: Playback: CJRPlaybackEngine::Play: Finish (453 ms)
0022953: 4584: Playback: CPlayerZone::Play: Play succeeded
0022953: 4772: Playback: CPlayerZone::OnNewStream: Finish (0 ms)
0022968: 4772: Playback: CMJPlayerCore::GetOutputFormat: Start
0022984: 4772: Playback: CMJPlayerCore::GetOutputFormat: Using input format
0022984: 4772: Playback: CMJPlayerCore::GetOutputFormat: wFormatTag 1
0022968: 4544: Reader: CLocalReader::OpenInternal: Opening: D:\Music\Opera_4\History of Opera\Vol 05\Folder.jpg
OutputFormat: nSamplesPerSec 44100
0022968: 4584: Playback: CPlayerZone::Play: Finish (672 ms)
0023000: 4772: Playback: CMJPlayerCore::GetOutputFormat: nAvgBytesPerSec 176400
0023015: 4772: Playback: CMJPlayerCore::GetOutputFormat: nBlockAlign 4
0023015: 4772: Playback: CMJPlayerCore::GetOutputFormat: wBitsPerSample 16
0023015: 4584: Reader: CLocalReader::OpenInternal: Opening: C:\Program Files (x86)\J River\Media Center 13\Data\Default Art\ActionWindowNavigation.png
0023031: 4584: Reader: CLocalReader::Close: Closing: C:\Program Files (x86)\J River\Media Center 13\Data\Default Art\ActionWindowNavigation.png
0023031: 4772: Playback: CMJPlayerCore::GetOutputFormat: cbSize 0
0023046: 4584: General: CMainUIWnd::Resize: Start
0023046: 4772: Playback: CMJPlayerCore::GetOutputFormat: Finish (78 ms)
0023046: 4772: Playback: CMJPlayerCore::GetOutputFormat: Start
0023062: 4772: Playback: CMJPlayerCore::GetOutputFormat: Using input format
0023062: 4772: Playback: CMJPlayerCore::GetOutputFormat: wFormatTag 1
0023078: 4772: Playback: CMJPlayerCore::GetOutputFormat: nChannels 2
0023078: 4584: Reader: CLocalReader::OpenInternal: Opening: C:\Program Files (x86)\J River\Media Center 13\MegaSkins\Noire\ActionWindow_Tools.png
0023078: 4772: Playback: CMJPlayerCore::GetOutputFormat: nSamplesPerSec 44100
0023093: 4772: Playback: CMJPlayerCore::GetOutputFormat: nAvgBytesPerSec 176400
0023093: 4584: Reader: CLocalReader::Close: Closing: C:\Program Files (x86)\J River\Media Center 13\MegaSkins\Noire\ActionWindow_Tools.png
0023125: 4772: Playback: CMJPlayerCore::GetOutputFormat: nBlockAlign 4
0023125: 4584: Reader: CLocalReader::OpenInternal: Opening: C:\Program Files (x86)\J River\Media Center 13\MegaSkins\Noire\ActionWindow_Restore.png
0023140: 4772: Playback: CMJPlayerCore::GetOutputFormat: wBitsPerSample 16
0023140: 4584: Reader: CLocalReader::Close: Closing: C:\Program Files (x86)\J River\Media Center 13\MegaSkins\Noire\ActionWindow_Restore.png
0023156: 4772: Playback: CMJPlayerCore::GetOutputFormat: cbSize 0
0023156: 4584: General: CMainUIWnd::Resize: Finish (110 ms)
0023171: 4772: Playback: CMJPlayerCore::GetOutputFormat: Finish (125 ms)
0023234: 3472: Playback: CWaveOutBinPlayThread::Thread: Start
0023234: 4772: Playback: CMJWaveFeeder::Thread: Preparing to feed data
0023265: 4772: Playback: CMJWaveFeeder::Thread: Running feeder loop
0023750: 4584: Reader: CLocalReader::OpenInternal: Opening: C:\Program Files (x86)\J River\Media Center 13\MegaSkins\Noire\PlayerBar_PauseButton.png
0023750: 4584: Reader: CLocalReader::Close: Closing: C:\Program Files (x86)\J River\Media Center 13\MegaSkins\Noire\PlayerBar_PauseButton.png
0031109: 4584: General: CMCToolsCore::StopTools: Start
0031109: 4584: General: CMCToolsCore::StopTools: Stopping tools
0031125: 4584: General: CMCToolsCore::StopTools: Stopping loader thread
0031125: 4584: General: CLoaderThread::~CLoaderThread: Start
0031156: 4584: General: CLoaderThread::~CLoaderThread: Stopping thread
0031171: 4584: General: CLoaderThread::~CLoaderThread: Clearing save timer
0031203: 4584: General: CLoaderThread::~CLoaderThread: Stopping worker threads
0031203: 4584: General: CLoaderThread::~CLoaderThread: Revoking automation
0031218: 4584: SDK: CMJAutomation::~CMJAutomation: Global Count: 1
0031218: 4584: General: CLoaderThread::~CLoaderThread: Restoring system settings
0031234: 4584: General: CLoaderThread::~CLoaderThread: Finish (109 ms)
0031234: 4584: General: CMCToolsCore::StopTools: Destroying synchronize database
0031250: 4732: General: CGetCoverArtWorker::GetAudioImage: Start
0031265: 4732: General: CGetCoverArtWorker::GetAudioImage: Searching player backend for cover art failed.
0031296: 4732: Reader: CInternetReader::Open: Start
0031296: 4732: Reader: CInternetReader::Open: Opening http://www.yadb.com/cgi-bin/CoverArtGetList.cgi?Artist=(Baltsa-Carreras)&Album=Opera%20Duets%202&Tool=Auto-Import
0031312: 2876: Reader: CInternetReader::Thread: Start
0031328: 2876: Reader: CInternetReader::DownloadFromHTTPURL: Start
0031421: 2876: Reader: CInternetReader::DownloadFromHTTPURL: HttpSendRequest error: 12029
0031421: 2876: Reader: CInternetReader::DownloadFromHTTPURL: Failed (header status code: -1)
0031437: 2876: Reader: CInternetReader::DownloadFromHTTPURL: Finish (109 ms)
0031437: 2876: Reader: CInternetReader::Thread: Finish (125 ms)
0031453: 4732: Reader: CInternetReader::Open: ConnectToURL failed, m_bConnectError=TRUE, URL=http://www.yadb.com/cgi-bin/CoverArtGetList.cgi?Artist=(Baltsa-Carreras)&Album=Opera%20Duets%202&Tool=Auto-Import
0031453: 4732: Reader: CInternetReader::Open: Finish (157 ms)
0031468: 4732: Reader: CInternetReader::Close: Start
0031468: 4732: Reader: CInternetReader::Close: Finish (0 ms)
0031484: 4732: General: CGetCoverArtWorker::GetAudioImage: Searching YADB for cover art failed.
0031484: 4732: General: CGetCoverArtWorker::GetAudioImage: Finish (234 ms)
0031500: 4732: Reader: CLocalReader::OpenInternal: Opening: C:\Users\dale\AppData\Roaming\J River\Media Center 13\Library\field (audio analysis info).jmd
0031515: 4732: Database: CDataHolder::Load: Field: Audio Analysis Info; Files: 4690; Pointer bytes: 0; Data bytes: 48; Elapsed ms: 1.127
0041171: 4584: General: CMCToolsCore::StopTools: Destroying handheld engine
0041171: 4584: General: CMCToolsCore::StopTools: Destroying podcasting
0041187: 4584: General: CMCToolsCore::StopTools: Stopping scheduler
0041187: 4584: General: CMCToolsCore::StopTools: Destroying TV guide scanner
0041203: 4584: General: CMCToolsCore::StopTools: Stopping TV recording
0041203: 4584: General: CMCToolsCore::StopTools: Unloading hotkeys
0041218: 4584: General: CMCToolsCore::StopTools: Cancelling downloads
0041218: 4584: General: CDownloadQueue::Cancel: Start
0041234: 4584: General: CDownloadQueue::Cancel: ID=-1
0041234: 4584: General: CDownloadQueue::Cancel: elapsed time before cancel loop = 15
0041250: 4584: General: CDownloadQueue::Cancel: elapsed time for cancel loop = 11
0041250: 4584: General: CDownloadQueue::Cancel: elapsed time for RemoveDeadTasks = 0
0041250: 4584: General: CDownloadQueue::Cancel: Finish (32 ms)
0041250: 4584: General: CMCToolsCore::StopTools: Saving MRU information
0041265: 4584: General: CMCToolsCore::StopTools: Finish (10156 ms)

[dpetr]

Problem resolved.

Debug output=
0037188: 940: Reader: CLocalReader::OpenInternal: Opening: C:\Users\dale\AppData\Roaming\J River\Media Center 13\Library\field (audio analysis info).jmd
(39c.3ac): C++ EH exception - code e06d7363 (first chance)
0037188: 940: Database: CDataHolder::Load: Field: Audio Analysis Info; Files: 4700; Pointer bytes: 0; Data bytes: 48; Elapsed ms: 1.256
(Hangs after this one)

And of course, there's no "field (audio analysis info).jmb" in that directory.

Turned off audio analysis in options.  All is now normal.

Note:  there wasn't one in the equivalent MC12 directory either.  New feature?

[Matt]

Problem resolved.

Debug output=
0037188: 940: Reader: CLocalReader::OpenInternal: Opening: C:\Users\dale\AppData\Roaming\J River\Media Center 13\Library\field (audio analysis info).jmd
(39c.3ac): C++ EH exception - code e06d7363 (first chance)
0037188: 940: Database: CDataHolder::Load: Field: Audio Analysis Info; Files: 4700; Pointer bytes: 0; Data bytes: 48; Elapsed ms: 1.256
(Hangs after this one)

And of course, there's no "field (audio analysis info).jmb" in that directory.

Turned off audio analysis in options.  All is now normal.

Note:  there wasn't one in the equivalent MC12 directory either.  New feature?

It's fine for a library file to not exist -- it just means that field is empty.

I'm guessing that audio analysis (which runs in a low priority thread until your library is analyzed) isn't shutting down as quickly as it should on close.  We'll take a closer look.