Delayed Foobar2000 launch in Wine [BUG]

sonofevil commented 9 months ago

Describe the bug The script seems to take a very long time to initialize, delaying the appearance of the application window with no visible feedback on what's happening.

To Reproduce Steps to reproduce the behavior:

Launch Foobar2000 in Wine
Wait for window to open.
Check console log: script "initialized in 87344 ms"

Components loaded in: 0:02.576127
Configuration read in: 0:00.460550
foobar2000 v2.0 x86 [portable]
Library scanning problem: "H:\Music", reason: File not found.  
Folder watching failure: File not found.  
Watching: Z:\home\lutra\Music\Musik
Shell hook registration failure: 0
Playlist #0 loaded in 0:00.035536
Minibar scanning Z:\home\lutra\Music\Musik\Chevalier\Chevalier - Destiny Calls (2019)\1 Introduction.mp3
Track scanned in 535.499 ms
myLibrary init
myInitStageCallback init
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getRecentTracks&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&limit=200&format=json&from=1707264538&page=1
Library initialized after 0:19.687667
Playlist manager: reading files from "Z:\home\lutra\.foobar2000\profile\playlist_manager\"
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chevalier&track=Stormbringer&limit=200&format=json&page=1
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chevalier&track=In The Grip Of Night&limit=200&format=json&page=1
Found 1 scrobbles in last.fm (since last known scrobble at 2021-01-28 14:59:12) of "Stormbringer"
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chevalier&track=In The Grip Of Night&limit=200&format=json&page=1
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chevalier&track=Prelude To The End&limit=200&format=json&page=1
Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: loadPlaylistsFromFolder): 3390ms
Playlist #1 loaded in 0:00.069469
Playlist #2 loaded in 0:00.022332
Playlist #3 loaded in 0:00.054717
Playlist #38 loaded in 0:00.081994
Playlist #39 loaded in 0:00.063134
Found 6 scrobbles in last.fm of "In The Grip Of Night"
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chevalier&track=A Warrior's Lament&limit=200&format=json&page=1
Found 1 scrobbles in last.fm (since last known scrobble at 2021-01-28 15:04:42) of "In The Grip Of Night"
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chevalier&track=A Warrior's Lament&limit=200&format=json&page=1
Found 1 scrobbles in last.fm (since last known scrobble at 2021-01-28 15:11:06) of "Prelude To The End"
Found 1 scrobbles in last.fm (since last known scrobble at 2021-01-28 15:12:45) of "A Warrior's Lament"
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chevalier&track=Outro&limit=200&format=json&page=1
Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chevalier&track=Outro&limit=200&format=json&page=1
Found 6 scrobbles in last.fm of "Outro"
Found 1 scrobbles in last.fm (since last known scrobble at 2021-01-28 15:20:33) of "Outro"
Found 6 scrobbles in last.fm of "A Warrior's Lament"
Playlist #43 loaded in 0:00.030526
Spider Monkey Panel v1.6.1 ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: Playlist-Manager-SMP v0.12.1 by Regorxxx): initialized in 87344 ms
User Interface initialized in: 1:29.135454

Expected behavior The application appears after a reasonable amount of time.

Desktop (please complete the following information):

OS: EndeavourOS/Wine
Browser: Wine browser
Version: 0.12.1

It is annoying that F2k to my knowledge doesn't offer any way to redirect the console log to standard output in a terminal. I cannot say for sure what exactly is delaying the launch until I can watch the launch output in real time and insert timestamps in bash, but the console is only accessible once the Window appears and writing to log file automatically gets disabled when Foobar2000 is closed. Closed source nonsense.

sonofevil commented 9 months ago

Nevermind, logging to file stays enabled. So here are some timestamps:

[2024-02-07 18:16:07.708] Components loaded in: 0:01.838186
[2024-02-07 18:16:08.292] Configuration read in: 0:00.336402
[2024-02-07 18:16:08.292] foobar2000 v2.0 x86 [portable]
[2024-02-07 18:16:08.373] Library scanning problem: "H:\Music", reason: File not found.  
[2024-02-07 18:16:08.398] Folder watching failure: File not found.  
[2024-02-07 18:16:08.522] Watching: Z:\home\lutra\Music\Musik
[2024-02-07 18:16:12.725] Shell hook registration failure: 0
[2024-02-07 18:16:12.986] Playlist #12 loaded in 0:00.015217
[2024-02-07 18:16:13.187] Minibar scanning Z:\home\lutra\Music\Musik\Assück\Assuck.1997.Misery Index\05. Blight of Element.mp3
[2024-02-07 18:16:13.554] Track scanned in 366.908 ms
[2024-02-07 18:16:14.006] myLibrary init
[2024-02-07 18:16:14.012] myInitStageCallback init
[2024-02-07 18:16:14.020] Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getRecentTracks&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&limit=200&format=json&from=1707314577&page=1
[2024-02-07 18:16:14.125] Library initialized after 0:08.329239
[2024-02-07 18:16:18.502] Playlist manager: reading files from "Z:\home\lutra\.foobar2000\profile\playlist_manager\"
[2024-02-07 18:16:19.982] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: loadPlaylistsFromFolder): 1436ms
[2024-02-07 18:16:20.069] Playlist #0 loaded in 0:00.082995
[2024-02-07 18:16:20.174] Playlist #1 loaded in 0:00.104425
[2024-02-07 18:16:20.744] Playlist #2 loaded in 0:00.013680
[2024-02-07 18:16:20.765] Playlist #3 loaded in 0:00.019740
[2024-02-07 18:16:20.916] Playlist #37 loaded in 0:00.047518
[2024-02-07 18:16:20.974] Playlist #38 loaded in 0:00.056728
[2024-02-07 18:16:59.952] Playlist #42 loaded in 0:00.005980
[2024-02-07 18:17:00.019] Spider Monkey Panel v1.6.1 ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: Playlist-Manager-SMP v0.12.1 by Regorxxx): initialized in 46694 ms
[2024-02-07 18:17:00.519] User Interface initialized in: 0:47.797503

regorxxx commented 9 months ago

Need more info about this... like:

Amount of playlists files on the tracked folder
Autoplaylists?
Which version exhibits this behavior?

Also note this:

[2024-02-07 18:16:20.974] Playlist #38 loaded in 0:00.056728 [2024-02-07 18:16:59.952] Playlist #42 loaded in 0:00.005980

You said its the panel the one taking a lot of time to load, but there is a gap of time between loading these 2 playlists of 39 seconds (?)

sonofevil commented 9 months ago

Need more info about this... like:

* Amount of playlists files on the tracked folder

* Autoplaylists?

* Which version exhibits this behavior?

There are now 35 physical playlists, 5 UI-only playlists and no autoplaylists.

Script: 0.12.1 Foobar2000: 2.0 SMP: 1.6.1

Also note this:

[2024-02-07 18:16:20.974] Playlist #38 loaded in 0:00.056728 [2024-02-07 18:16:59.952] Playlist #42 loaded in 0:00.005980

You said its the panel the one taking a lot of time to load, but there is a gap of time between loading these 2 playlists of 39 seconds (?)

Yeah I noticed this, how do I figure out which playlist has which number?

sonofevil commented 9 months ago

Oh god it seems I deleted the problematic playlist and didn't realize they couldn't be restored after restarting F2k. Now the delay is gone and I don't know how to reproduce it. I guess I'll reopen if it happens again.

regorxxx commented 9 months ago

Ups, sorry. But note the manager autobackups files! If it's a physical playlist, you can restore it. Look at the tracked folder '_backup' subfolder.

Can not do anything with UI playlists though. Unless you use foo_jesus or my autobackup button script.

Also use the nightly version, I probably fixed it in some way after the official release (and it's pretty stable now).

If you find a problem again, let me know. It was really weird to have a problem with a single playlist...

sonofevil commented 9 months ago

Alright, this is from the current nightly:

[2024-02-14 17:10:07.383] Components loaded in: 0:03.052350
[2024-02-14 17:10:14.791] Configuration read in: 0:00.176933
[2024-02-14 17:10:14.791] foobar2000 v2.0 x86 [portable]
[2024-02-14 17:10:15.033] Library scanning problem: "H:\Music", reason: File not found.  
[2024-02-14 17:10:15.059] Folder watching failure: File not found.  
[2024-02-14 17:10:15.599] Watching: Z:\home\lutra\Music\Musik
[2024-02-14 17:10:21.901] Shell hook registration failure: 0
[2024-02-14 17:10:22.276] Playlist #36 loaded in 0:00.011867
[2024-02-14 17:10:22.608] Minibar scanning Z:\home\lutra\Music\Musik\Chaos Moon\Chaos Moon - Origin of Apparition-Languor into Echoes- Beyond - 10th Anniversary\Chaos Moon - Origin of Apparition-Languor into Echoes, Beyond - 10th Anniversary - 01 Illusions of Dusk and Dawn (Origin).mp3
[2024-02-14 17:10:24.289] Track scanned in 1681.044 ms
[2024-02-14 17:10:24.474] myLibrary init
[2024-02-14 17:10:24.480] myInitStageCallback init
[2024-02-14 17:10:24.489] Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getRecentTracks&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&limit=200&format=json&from=1707907752&page=1
[2024-02-14 17:10:24.539] Library initialized after 0:20.330882
[2024-02-14 17:10:34.152] Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getTrackScrobbles&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&artist=Chaos Moon&track=Origin of Apparition&limit=200&format=json&page=1
[2024-02-14 17:10:34.497] Found 1 scrobbles in last.fm (since last known scrobble at 2024-02-14 14:15:46) of "Origin of Apparition"
[2024-02-14 17:10:36.567] Playlist manager: reading files from "Z:\home\lutra\.foobar2000\profile\playlist_manager\"
[2024-02-14 17:10:39.371] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: loadPlaylistsFromFolder): 2750ms
[2024-02-14 17:10:39.408] Playlist #0 loaded in 0:00.034933
[2024-02-14 17:10:39.472] Playlist #1 loaded in 0:00.062890
[2024-02-14 17:10:39.640] Playlist #2 loaded in 0:00.001239
[2024-02-14 17:10:39.673] Playlist #3 loaded in 0:00.032442
[2024-02-14 17:10:39.987] Playlist #24 loaded in 0:00.048717
[2024-02-14 17:11:56.885] Spider Monkey Panel v1.6.1 ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: Playlist-Manager-SMP v0.12.1 by Regorxxx): initialized in 94036 ms
[2024-02-14 17:11:57.647] User Interface initialized in: 1:35.774622

There isn't any notable gap between loading playlists here, so I guess that was unrelated.

regorxxx commented 9 months ago

It's really impossible to know what's going on with that.

Are you using lite mode?
Previous versions had the same problem? (which one)
Does it happen on panel reload or only on foobar init?
And finally, download the latest nightly and install over current panel. Go to '[FOOBAR PROFILE FOLDER]\js_data\presets\global\globSettings.json' and set "bProfileInit" to true. Then perform your usual test and post the console log here, it should provide detailed times about specific steps at loading.

regorxxx commented 9 months ago

Any news on this?

sonofevil commented 9 months ago

Sorry, been dealing with some personal stuff, but it's on the back of my mind.

sonofevil commented 8 months ago

It's really impossible to know what's going on with that.

1. Are you using lite mode?

2. Previous versions had the same problem? (which one)

3. Does it happen on panel reload or only on foobar init?

4. And finally, download the latest nightly and install over current panel. Go to '[FOOBAR PROFILE FOLDER]\js_data\presets\global\globSettings.json' and set "bProfileInit" to true. Then perform your usual test and post the console log here, it should provide detailed times about specific steps at loading.

Nope, nearly all features enabled.
I just installed the latest Nightly and the problem persists. I can't say if it was present before 0.12.1. It certainly wasn't as bad in the past. But I jumped from like 0.5 to 0.12 at one point.
Foobar init only, it seems.

[2024-03-01 23:25:15.805] Components loaded in: 0:02.472056
[2024-03-01 23:25:18.779] Configuration read in: 0:00.203803
[2024-03-01 23:25:18.779] foobar2000 v2.0 x86 [portable]
[2024-03-01 23:25:18.913] Watching: Z:\home\lutra\Music\Musik
[2024-03-01 23:25:23.351] Shell hook registration failure: 0
[2024-03-01 23:25:23.646] Playlist #32 loaded in 0:00.006267
[2024-03-01 23:25:23.933] Minibar scanning Z:\home\lutra\Music\Musik\Manilla Road\Voyager\01-Tomb Of The Serpent King - Butchers Of The Sea.mp3
[2024-03-01 23:25:24.740] myLibrary init
[2024-03-01 23:25:24.741] myInitStageCallback init
[2024-03-01 23:25:24.758] Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getRecentTracks&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&limit=200&format=json&from=1709327357&page=1
[2024-03-01 23:25:24.839] Library initialized after 0:11.535103
[2024-03-01 23:25:26.147] Track scanned in 2213.771 ms
[2024-03-01 23:25:26.381] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.vars 1ms
[2024-03-01 23:25:26.578] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.internals 198ms
[2024-03-01 23:25:26.586] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.fileSystem 205ms
[2024-03-01 23:25:26.596] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.scripting 216ms
[2024-03-01 23:25:26.604] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.ui 224ms
[2024-03-01 23:25:26.619] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.os 239ms
[2024-03-01 23:25:26.673] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): helpers_xxx 293ms
[2024-03-01 23:25:28.977] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): helpers 2597ms
[2024-03-01 23:25:29.050] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): init 2671ms
[2024-03-01 23:25:29.060] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.prototype 2681ms
[2024-03-01 23:25:29.061] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.prototype 2682ms
[2024-03-01 23:25:29.378] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): initCheckFeatures 2998ms
[2024-03-01 23:25:30.454] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.settings 4075ms
[2024-03-01 23:25:30.456] Playlist manager: reading files from "Z:\home\lutra\.foobar2000\profile\playlist_manager\"
[2024-03-01 23:25:32.905] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: loadPlaylistsFromFolder): 2422ms
[2024-03-01 23:25:32.948] Playlist #0 loaded in 0:00.033938
[2024-03-01 23:25:32.989] Playlist #1 loaded in 0:00.036581
[2024-03-01 23:25:33.196] Playlist #2 loaded in 0:00.021595
[2024-03-01 23:25:33.243] Playlist #18 loaded in 0:00.045830
[2024-03-01 23:26:42.264] Playlist #26 loaded in 0:00.007118
[2024-03-01 23:26:42.336] Playlist #40 loaded in 0:00.034783
[2024-03-01 23:26:42.398] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.playlists 76019ms
[2024-03-01 23:26:42.400] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.post 76021ms
[2024-03-01 23:26:42.405] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): callbacks 76026ms
[2024-03-01 23:26:42.405] Spider Monkey Panel v1.6.1 ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: Playlist-Manager-SMP v0.13.0 by Regorxxx): initialized in 78340 ms
[2024-03-01 23:26:42.920] User Interface initialized in: 1:19.573630
[2024-03-01 23:26:42.925] Graphic Equalizer: initialized (SSE support: 3)
[2024-03-01 23:26:42.930] FFmpeg version: 6.0
[2024-03-01 23:26:43.106] Loading
[2024-03-01 23:26:43.244] beefweb: failed to bind to address [0.0.0.0]:8888: bind: Access denied [system:10013 at D:\a\beefweb\beefweb\cpp\build\Release\extlibs-root\include\boost/asio/detail/win_iocp_socket_service.hpp:244:5 in function 'bind']
[2024-03-01 23:26:43.314] foo_enhanced_playcount: loaded
[2024-03-01 23:26:43.321] Startup time : 1:30.017790
[2024-03-01 23:26:47.531] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.vars 81152ms
[2024-03-01 23:26:47.540] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.internals 81161ms
[2024-03-01 23:26:47.542] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.fileSystem 81163ms
[2024-03-01 23:26:47.543] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.scripting 81164ms
[2024-03-01 23:26:47.544] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.ui 81165ms
[2024-03-01 23:26:47.550] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.os 81171ms

sonofevil commented 8 months ago

Upon restart, it also hangs after playlist #18.

For comparison, when reloading panel:

[2024-03-01 23:34:05.497] Spider Monkey Panel v1.6.1: profiler (Playlist manager Backup): 13575ms
[2024-03-01 23:34:11.733] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.vars 60ms
[2024-03-01 23:34:12.034] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.internals 375ms
[2024-03-01 23:34:12.093] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.fileSystem 427ms
[2024-03-01 23:34:12.149] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.scripting 490ms
[2024-03-01 23:34:12.169] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.ui 507ms
[2024-03-01 23:34:12.261] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.os 594ms
[2024-03-01 23:34:12.381] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): helpers_xxx 714ms
[2024-03-01 23:34:14.694] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): helpers 3038ms
[2024-03-01 23:34:14.880] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): init 3224ms
[2024-03-01 23:34:14.947] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.prototype 3291ms
[2024-03-01 23:34:14.956] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.prototype 3298ms
[2024-03-01 23:34:20.501] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.settings 8840ms
[2024-03-01 23:34:20.504] Playlist manager: reading files from "Z:\home\lutra\.foobar2000\profile\playlist_manager\"
[2024-03-01 23:34:25.485] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: loadPlaylistsFromFolder): 4934ms
[2024-03-01 23:34:25.910] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.playlists 14254ms
[2024-03-01 23:34:25.934] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.post 14277ms
[2024-03-01 23:34:25.963] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): callbacks 14307ms
[2024-03-01 23:34:25.964] Spider Monkey Panel v1.6.1 ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: Playlist-Manager-SMP v0.13.0 by Regorxxx): initialized in 20101 ms
[2024-03-01 23:34:25.973] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): initCheckFeatures 14317ms
[2024-03-01 23:34:28.166] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.vars 16508ms
[2024-03-01 23:34:28.379] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.internals 16719ms
[2024-03-01 23:34:28.398] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.fileSystem 16740ms
[2024-03-01 23:34:28.417] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.scripting 16757ms
[2024-03-01 23:34:28.461] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.ui 16793ms
[2024-03-01 23:34:28.569] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): getSoFeatures.os 16913ms
[2024-03-01 23:34:30.070] Caching library paths 0%.
[2024-03-01 23:34:30.763] Caching library paths 10%.
[2024-03-01 23:34:31.967] Caching library paths 20%.
[2024-03-01 23:34:32.691] Caching library paths 30%.
[2024-03-01 23:34:34.140] Caching library paths 40%.
[2024-03-01 23:34:35.804] Caching library paths 50%.
[2024-03-01 23:34:37.258] Caching library paths 60%.
[2024-03-01 23:34:38.755] Caching library paths 70%.
[2024-03-01 23:34:39.237] Caching library paths 80%.
[2024-03-01 23:34:40.457] Caching library paths 90%.
[2024-03-01 23:34:42.018] Caching library paths 100%.
[2024-03-01 23:34:42.517] Playlist Manager: Created dynamic menus
[2024-03-01 23:34:59.958] Playlist manager: Cached playlists for searching (all)

regorxxx commented 8 months ago

Thing is this is clearly a SMP/foobar/system problem, since panel loads much faster on reload than on init. Which is something out of my control.

I can only delay things, like playlist loading, but delaying it only may make the panel UI to load "faster" although it will be unusable until all loads.

Also, in general your foobar instance takes a lot of time for anything.. not sure if it's also a problem with your PC or drive being too slow. In my pc it takes like 100ms to load all up to the init step, yours takes 3 seconds. That's not normal, and it's only related to loading the script files (so it's the same for everybody, no matter their UI or playlist files).

Panel reload with 80 playlist files and 40 autoplaylists (+ full features):

[22:13:29] Spider Monkey Panel v1.6.1-mod: profiler (Playlist manager Backup): 54ms [22:13:29] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): initCheckFeatures 2ms [22:13:29] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): helpers_xxx 4ms [22:13:29] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): helpers 98ms [22:13:29] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): init 110ms [22:13:29] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): list.prototype 119ms [22:13:29] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): list.init.prototype 119ms [22:13:29] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): list.init.settings 187ms [22:13:29] Playlist manager: reading files from "C:\Users\XXX\AppData\Roaming\foobar2000\playlist_manager\server\" [22:13:30] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2: loadPlaylistsFromFolder): 179ms [22:13:30] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): list.init.playlists 385ms [22:13:30] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): list.init.post 387ms [22:13:30] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2 - Global profiler): callbacks 392ms [22:13:30] Spider Monkey Panel v1.6.1-mod (Playlist Manager 2: Playlist Manager v0.13.0 by regorxxx): initialized in 572 ms [22:13:30] precacheLibraryPaths: using paths from another instance. Playlist Manager 2 [22:13:40] Spider Monkey Panel v1.6.1-mod: profiler (Playlist Manager 2: Refresh AutoPlaylists): 10126ms [22:13:40] Playlist Manager: Created dynamic menus

Create a new blank panel and check it yourself. There is definitely something wrong on your side.

I have pushed a new nightly anyway which skips OS features checks, which sometimes hang foobar at init.

Go to '[FOOBAR PROFILE FOLDER]\js_data\presets\global\globSettings.json' and set "bCheckSoFeatures" to false. Then perform your usual test and post the console log here. All 'getSoFeatures' entries should be gone.

regorxxx commented 8 months ago

That's said, I'm open to further testing and trying to optimize things as much as possible, but all leads to a bottleneck on your side.

sonofevil commented 8 months ago

I have pushed a new nightly anyway which skips OS features checks, which sometimes hang foobar at init.

Go to '[FOOBAR PROFILE FOLDER]\js_data\presets\global\globSettings.json' and set "bCheckSoFeatures" to false. Then perform your usual test and post the console log here. All 'getSoFeatures' entries should be gone.

[2024-03-04 22:50:58.885] Components loaded in: 0:01.812743
[2024-03-04 22:50:59.829] Configuration read in: 0:00.537392
[2024-03-04 22:50:59.829] foobar2000 v2.0 x86 [portable]
[2024-03-04 22:50:59.988] Watching: Z:\home\lutra\Music\Musik
[2024-03-04 22:51:04.307] Shell hook registration failure: 0
[2024-03-04 22:51:04.720] Playlist #46 loaded in 0:00.028493
[2024-03-04 22:51:05.131] Minibar scanning Z:\home\hauke\Music\phonesync\WIEGEDOOD\DE DODEN HEBBEN HET GOED II\01-ONTZIELING.mp3
[2024-03-04 22:51:05.990] myLibrary init
[2024-03-04 22:51:05.991] myInitStageCallback init
[2024-03-04 22:51:06.048] Querying last.fm: http://ws.audioscrobbler.com/2.0/?method=user.getRecentTracks&api_key=a1685abe5265b93cf2be4a70d181bf6b&user=Endzeitlager&limit=200&format=json&from=1709582463&page=1
[2024-03-04 22:51:06.288] Library initialized after 0:09.292409
[2024-03-04 22:51:08.522] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): initCheckFeatures 197ms
[2024-03-04 22:51:08.700] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): helpers_xxx 379ms
[2024-03-04 22:51:09.215] Track scanned in 4084.309 ms
[2024-03-04 22:51:12.336] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): helpers 4018ms
[2024-03-04 22:51:12.478] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): init 4160ms
[2024-03-04 22:51:12.523] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.prototype 4205ms
[2024-03-04 22:51:12.525] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.prototype 4207ms
[2024-03-04 22:51:13.918] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.settings 5600ms
[2024-03-04 22:51:13.919] Playlist manager: reading files from "Z:\home\lutra\.foobar2000\profile\playlist_manager\"
[2024-03-04 22:51:15.321] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: loadPlaylistsFromFolder): 1386ms
[2024-03-04 22:51:15.344] Playlist #0 loaded in 0:00.020172
[2024-03-04 22:51:15.373] Playlist #1 loaded in 0:00.026628
[2024-03-04 22:51:15.490] Playlist #2 loaded in 0:00.001296
[2024-03-04 22:51:15.553] Playlist #17 loaded in 0:00.060822
[2024-03-04 22:52:11.391] Playlist #24 loaded in 0:00.044789
[2024-03-04 22:52:11.476] Playlist #32 loaded in 0:00.021201
[2024-03-04 22:52:11.530] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.playlists 63211ms
[2024-03-04 22:52:11.532] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): list.init.post 63214ms
[2024-03-04 22:52:11.541] Spider Monkey Panel v1.6.1: profiler ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC} - Global profiler): callbacks 63223ms
[2024-03-04 22:52:11.542] Spider Monkey Panel v1.6.1 ({9AEA37B9-213C-4E77-B34D-4ABC5647E8EC}: Playlist-Manager-SMP v0.13.0 by Regorxxx): initialized in 66292 ms
[2024-03-04 22:52:12.461] User Interface initialized in: 1:08.180492

A bit better but still too long. I'll have to keep looking for what could possibly cause that bottleneck.

sonofevil commented 8 months ago

Any suggestions for figuring out which playlist is taking so long to load?

regorxxx commented 8 months ago

I don't think it's related at all to any particular playlist, is your general foobar instance the one takes so much time.

Anway, maybe it's a playlist with dead files? Make a copy of all of them, and try leaving half of them in the UI at every step. Until you find if there is a problematic one.

Last nightly includes a new setting to delay playlist loading. You can set it to 30 secs or something like that...

regorxxx commented 8 months ago

New one also includes settings for other steps at init.

regorxxx commented 7 months ago

Does the new settings help with your problem or has it been solved?

sonofevil commented 7 months ago

It's still slow but not as slow as it used to be. I can probably live with it. I rarely even notice anymore since I just put f2k in autostart. I think there is no good reason to keep this open. Thanks for the help tho.

regorxxx / Playlist-Manager-SMP

Delayed Foobar2000 launch in Wine [BUG] #78