Servant Salamander and file type association (CPU load)

Foobar2000User · Post by **Foobar2000User** » 01 Feb 2009, 21:43

I used the the 2.5 beta 1 for a few days, and i had installed Foobar2000 0.9.5 (a popular free music player). Files with .mp3 extension are associated with foobar2000. When i double-clicked any .mp3 file (from Windows Explorer or Servant Salamander, Foobar2000 would be started and played the song.

After updating the Foobar2000 version to 0.9.6.2 i noticed that Servant Salamander takes about 15 seconds of 100% CPU load (kind of locks my computer up) when clicking a .mp3 file, while clicking the same file from Windows Explorer starts the associated Foobar2000 fine (without the high CPU load).

It happens with every Foobar2000 associated file and only from within Servant Salamander.

That only happens if Foobar2000 isn't running (if it is running, Foobar2000 changes the file played to the clicked one without any problems).

I reproduced this strange behaviour with a "virgin" Windows XP SP3 running on a virtual machine (VirtualBox). The same behaviour remains when using latest Servant Salamander Demo 2.52 beta 1. I also tested the "open files through salopen.exe" option with no different experience.

If it is any help. Here is a link to a screenshot that shows the 30 second (!) gap where Servant Salamander hangs (recorded with Sysinternals ProcessMonitor).

I also found this at Foobar2000 support forum - it's from a changelog of a 0.9.6 beta version of Foobar2000:

Code: Select all

Improved compatibility of file type associations with Windows Vista.

Maybe Servant Salamander has problems with these "improved" file type associations for Vista.

Edit: Okay, i've deleted these "improved" file type associations and just pointed to foobar2000.exe when asked to associate a program with file extension .mp3 ... and voilà ... it works as it should ... Servant Salamander seems to have problems with certain file associations. I am sure that problem exists for other file type associations, too. I will make more tests to find the difference between these two associations.

Greetings,
Erebos (Germany)

Post by **Jan Rysavy** » 02 Feb 2009, 18:11

Hi, thank you for the detailed report. Could you please start two instances of Salamander and break the hanged one? Use the Help > Task List command from Salamander menu. The bug report with call stack should be displayed.

Tried to install Foobar2000 0.9.6.2 on my Windows Vista 64b Ultimate and it looks ok.

Post by **zarevak** » 02 Feb 2009, 19:19

Hi, I'm able to reproduce the problem on my virtual Windows 7 32-bit with foobar2000 0.9.6.2 on single core CPU. There are few interresting points:
- my test extension (wave - previously unassigned) is not visible under HKEY_CLASSES_ROOT, but under: HKEY_CURRENT_USER\Software\Microsoft\Windows\CurrentVersion\Explorer\FileExts\.WAVE
- Salamander doesn't display icon for my chimes.wave file.
- foobar2000 is started right away - there is visible process in Process Explorer.
- internally Salamander is waiting on WaitForMultipleObjects deep in the sytem part of the stack
- foobar2000 window is not displayed until the wait is over
- there is no waiting time if foobar200 is already running
- if you "Break" Salamander from secong Salamander the Bug report window is not displayed until the waiting is over
- it seems the problem is in foobar2000, because there is a lot foobar2000 activity in Process Monitor, but no Salamander activity during the time

Call Stacks:
Thread ID: 0x4C0
WinMainBody(0x400000, , , 1)
WinMainBody::FindLatestConfiguration
WinMainBody::StartupDialog
WinMainBody::inicialization
WinMainBody::load_config
WinMainBody::message_loop
CFilesBox::WindowProc(0x203, 0x1, 0xA00035)
CFilesWindow::Execute(7)
ExecuteAssociation(, C:\Users\Ondra\Documents, chimes.wave)
ExecuteAssociation::1
ExecuteAssociation::2

Whole report on its way to support email

Post by **Jan Rysavy** » 03 Feb 2009, 16:11

zarevak wrote:- it seems the problem is in foobar2000, because there is a lot foobar2000 activity in Process Monitor, but no Salamander activity during the time

Could it be related to Folder watching mentioned in foobar2000 0.9.6 Release Notes?

Post by **zarevak** » 03 Feb 2009, 20:43

I've retested the issue and it seems it takes 10 seconds for the foobar2000 image and it's libraries to load. And it takes another 15 second for the foobar2000 to start doing anything. After it starts it starts loading many registry entries, but I suspect this is after Salamander is working again.

I revise my previous statement about problem being in foobar2000. It seems Salamander is creating high priority thread which is consuming all available CPU resources preventing process launch thread to initialize foobar2000 process. If you increase the foobar2000's base priority after it is started it launches right away, beacuse the launch thread overprioritizes the high CPU consuming Salamander's thread.

With Process Explorer I've been able to get this call stack of the Salamander's thread using most of the resources (foobar2000 at that time has only kernel-related launch thread):
ntkrnlpa.exe!KeWaitForMultipleObjects+0x1eb5
ntkrnlpa.exe!NtDuplicateToken+0x138c
ntkrnlpa.exe!KiDeliverApc+0x110
ntkrnlpa.exe!KeSynchronizeExecution+0x428
ntkrnlpa.exe!ExReleaseResourceLite+0xf
ntdll.dll!KiFastSystemCallRet
ShellExt32.dll+0x3be6
USER32.dll!EnumDisplayMonitors+0x8e
USER32.dll!EnumWindows+0x16
ShellExt32.dll+0x3c3f
ShellExt32.dll+0x3d3e
salamand.exe+0x941a3
USER32.dll!GetSystemMetrics+0x200
USER32.dll!GetSystemMetrics+0x32f
USER32.dll!GetWindowLongW+0x162
USER32.dll!SendMessageW+0x49
COMCTL32.dll!DPA_GetPtrIndex+0x131
SHELL32.dll!Ordinal99+0xde4
salamand.exe+0x1185d3
salamand.exe+0x1167e8
salamand.exe+0xdc4da
salamand.exe+0xe7105
salamand.exe+0x46f90
salamand.exe+0x3e502
salamand.exe+0x3fcd5
salamand.exe+0x3a09a
salamand.exe+0x1169a5
USER32.dll!GetSystemMetrics+0x200
USER32.dll!GetSystemMetrics+0x2d8
USER32.dll!GetSystemMetrics+0x907
USER32.dll!DispatchMessageA+0xf
salamand.exe+0xcc28e
salamand.exe+0xccb93
salamand.exe+0x11edd6
kernel32.dll!BaseThreadInitThunk+0x12
ntdll.dll!LdrInitializeThunk+0xed
ntdll.dll!LdrInitializeThunk+0xc0

Post by **zarevak** » 04 Feb 2009, 16:07

Jan Rysavy wrote:Please don't waste time with reporting Altap Salamander bugs in Windows 7. This system will not be supported until final version of Windows 7. Right now is Windows 7 (build 7000) just unfinished "technology preview", nothing more.

I've succesfully reproduced this problem on Windows Vista Business 32-bit single core under VMWare.

1) I've downloaded and installed AS2.52b1 and foobar2000 0.9.6.2
2) started foobar2000, selected "Visualization + Cover Art + Tabs" in "Dark Blue" as basic layout and went to "Preferences" to associate currently unassociated ".wave" files to foobar2000 (foobar2000 opens standard windows dialog and I select .wave and close the dialog). Then I've closed foobar2000.
3) started AS2.52b1 without importing old configuration, copied chimes.wav from Windows/Media to Desktop, renamed to chimes.wave and pressed Enter to start foobar2000.
4) High CPU usage is here!

BTW: The same problem is with AS2.51
Just to remind you: I'm not sure if Salamander recognizes the association, because foobar2000's icon is not shown
If you need more testing or some help, contact me on email or ICQ

Post by **Jan Rysavy** » 04 Feb 2009, 16:17

So it looks like poor scheduling in VMWare and VirtualBox.

We will lower Salamander's main (GUI) thread to normal priority before the context menu methods are called.

Thank you for your help! I will try to reproduce problem in VMWare.

Post by **zarevak** » 04 Feb 2009, 16:42

Jan Rysavy wrote:So it looks like poor scheduling in VMWare and VirtualBox.

I think it is more like a race condition. I've just tried it under Virtual PC with Windows 2008 (VS2010 CTP) and at first try it worked, but it didn't work the second time

Sadly I don't have any real computers with Vista or newer Windows...

Once more I'm revisiting my oppinion about the source of the problem - in the call stack I've posted here before there is a ShellExt32.dll library. This library is part of foobar2000 injected into Salamander as a shell extension

Post by **Jan Rysavy** » 04 Feb 2009, 17:37

zarevak wrote:Once more I'm revisiting my oppinion about the source of the problem - in the call stack I've posted here before there is a ShellExt32.dll library. This library is part of foobar2000 injected into Salamander as a shell extension

I think you nailed it! They are probably doing some heavy processing operations (enumeration?) in the shell extension and don't expect it will run in higher priority thread than foobar2000 GUI thread. However, the problem is on our side and will be solved in AS 2.52 beta 2.

Thanks for you time!