Game: while a save loads, worker threads sometimes wait the full 2 s for a virtual core and then run without one (main too) #262

Open
opened 2026-11-13 18:18:17 +00:00 by mooki · 2 comments
Member

Longshot version

main d4a69456 and main 0c74253d4, and the branch of pull request 66 at 3fc3c891

Channel

Built from source

What kind of problem

Something else

What happened

While the same Kokiri Forest save loads, some of the game's worker threads wait about two seconds for a virtual core they are allowed to run on, and then run without one. The two seconds are the existing escape deadline of vc_acquire in host/hos_thread.c, which is there to break a deadlock; the log line it writes is ran without a core after 2000 ms.

I noticed it while testing #66 (the Walk key) and first took it for something that change did. It is not: it happens on main as well, including this morning's main. Counted over ten start-ups on 13 November 2026:

Build Starts Starts with an escape Escape events
main @ d4a69456 4 1 1
pull request 66 @ 3fc3c891 4 2 4
main @ 0c74253d4 2 1 5

The starts alternated between old main and the pull request's build, followed by two of the newer main. Each run was stopped as soon as the scene was reached, with a cap of 120 seconds; all ten reached the scene and ended normally, with no fatal, device-loss or kernel-fault line. Shaders had been prepared beforehand, so shader preparation is not in these runs. No controller was connected and no key was pressed.

Order Build Escape events Observed post-play coverage before exit
1 main @ d4a69456 0 no complete present interval
2 pull request 66 @ 3fc3c891 3 no complete present interval
3 main @ d4a69456 0 0.115 s, 11 intervals
4 pull request 66 @ 3fc3c891 0 no complete present interval
5 main @ d4a69456 1 0.152 s, 18 intervals
6 pull request 66 @ 3fc3c891 0 0.059 s, 1 interval
7 main @ d4a69456 0 0.155 s, 17 intervals
8 pull request 66 @ 3fc3c891 1 0.059 s, 1 interval
9 main @ 0c74253d4 0 0.126 s, 23 intervals
10 main @ 0c74253d4 5 0.172 s, 21 intervals

What this does not establish:

  • The cause. The log names the waiting thread and the thread holding the core, but those names are not unique (six actor-creation threads share one), so the lines below do not identify the actual holder.
  • Any effect on play. No gap over one second between presented frames was found after play began, but the runs end right after the scene appears, so that covers a fraction of a second at most, and three runs have no complete interval at all. Longer play was not tested here.
  • That every long loading pause is one of these. Other reports of slow or frozen loading may have nothing to do with it.

No fix is proposed here and nothing was switched off. The two older builds contain a test-only key probe from the Walk work that was compiled in and not used in these runs; the build of main 0c74253d4 is plain.

Wanted: whether others see the line while loading. Searching your own longshot_log.txt for ran without a core is enough; the build, the place and your CPU would help.

Where in the game

Loading a save in Kokiri Forest (child), before play begins

How often

Sometimes

Graphics card and driver version

RTX 4090 24 GB, NVIDIA 615.78.08

CPU, RAM and operating system

Core i9-13900K, 96 GB RAM, Arch Linux (kernel 7.2.15)

Changes from the defaults

1920x1080, Custom profile, the game's own upscaler at 100%, frame generation off, no frame cap; run without a window

longshot_log.txt

pull request 66 @ 3fc3c891, start 2
[hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2001.0 ms: core 1: ModuleSystemWorker1 (16);
pull request 66 @ 3fc3c891, start 2
[hos bake::ModuleMgr] vcores: bake::ModuleMgr (priority 28) ran without a core after 2000.1 ms: core 1: tera::FileResourceMgr (25);
pull request 66 @ 3fc3c891, start 2
[hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.7 ms: core 1: GeneralFormatAsync_ (24);
main @ d4a69456, start 5
[hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.4 ms: core 5: ARes Loading 0 (19);
pull request 66 @ 3fc3c891, start 8
[hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.5 ms: core 2: BaseProcCreateAndDeleteThread (23);
main @ 0c74253d4, start 10
[hos bake::ModuleMgr] vcores: bake::ModuleMgr (priority 28) ran without a core after 2000.9 ms: core 1: ModuleSystemWorker1 (16);
main @ 0c74253d4, start 10
[hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2000.8 ms: core 1: ModuleSystemWorker1 (16);
main @ 0c74253d4, start 10
[hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.1 ms: core 1: BaseProcCreateAndDeleteThread (23);
main @ 0c74253d4, start 10
[hos aglTextureDataMgr::Compaction] vcores: aglTextureDataMgr::Compaction (priority 25) ran without a core after 2000.1 ms: core 1: ModuleSystemWorker1 (16);
main @ 0c74253d4, start 10
[hos tera::FileResourceMgr] vcores: tera::FileResourceMgr (priority 25) ran without a core after 2000.5 ms: core 1: ModuleSystemWorker1 (16);

Screenshots or video

None: nothing visible is wrong.

Before you send it

  • The problem is still there on the newest release or nightly.
  • I searched the open issues for it.
  • I'm not attaching game files, keys, the game's executable, its .bin caches or saves.

Not ticked: seen on main 0c74253d4 built from source on 13 November 2026, not on a downloaded nightly.

### Longshot version main d4a69456 and main 0c74253d4, and the branch of pull request 66 at 3fc3c891 ### Channel Built from source ### What kind of problem Something else ### What happened While the same Kokiri Forest save loads, some of the game's worker threads wait about two seconds for a virtual core they are allowed to run on, and then run without one. The two seconds are the existing escape deadline of `vc_acquire` in `host/hos_thread.c`, which is there to break a deadlock; the log line it writes is `ran without a core after 2000 ms`. I noticed it while testing https://git.magicbean.dev/MagicBeanDev/Longshot/pulls/66 (the Walk key) and first took it for something that change did. It is not: it happens on main as well, including this morning's main. Counted over ten start-ups on 13 November 2026: | Build | Starts | Starts with an escape | Escape events | |---|---:|---:|---:| | main @ d4a69456 | 4 | 1 | 1 | | pull request 66 @ 3fc3c891 | 4 | 2 | 4 | | main @ 0c74253d4 | 2 | 1 | 5 | The starts alternated between old main and the pull request's build, followed by two of the newer main. Each run was stopped as soon as the scene was reached, with a cap of 120 seconds; all ten reached the scene and ended normally, with no fatal, device-loss or kernel-fault line. Shaders had been prepared beforehand, so shader preparation is not in these runs. No controller was connected and no key was pressed. | Order | Build | Escape events | Observed post-play coverage before exit | |---|---|---:|---| | 1 | main @ d4a69456 | 0 | no complete present interval | | 2 | pull request 66 @ 3fc3c891 | 3 | no complete present interval | | 3 | main @ d4a69456 | 0 | 0.115 s, 11 intervals | | 4 | pull request 66 @ 3fc3c891 | 0 | no complete present interval | | 5 | main @ d4a69456 | 1 | 0.152 s, 18 intervals | | 6 | pull request 66 @ 3fc3c891 | 0 | 0.059 s, 1 interval | | 7 | main @ d4a69456 | 0 | 0.155 s, 17 intervals | | 8 | pull request 66 @ 3fc3c891 | 1 | 0.059 s, 1 interval | | 9 | main @ 0c74253d4 | 0 | 0.126 s, 23 intervals | | 10 | main @ 0c74253d4 | 5 | 0.172 s, 21 intervals | What this does not establish: - The cause. The log names the waiting thread and the thread holding the core, but those names are not unique (six actor-creation threads share one), so the lines below do not identify the actual holder. - Any effect on play. No gap over one second between presented frames was found after play began, but the runs end right after the scene appears, so that covers a fraction of a second at most, and three runs have no complete interval at all. Longer play was not tested here. - That every long loading pause is one of these. Other reports of slow or frozen loading may have nothing to do with it. No fix is proposed here and nothing was switched off. The two older builds contain a test-only key probe from the Walk work that was compiled in and not used in these runs; the build of main 0c74253d4 is plain. Wanted: whether others see the line while loading. Searching your own `longshot_log.txt` for `ran without a core` is enough; the build, the place and your CPU would help. ### Where in the game Loading a save in Kokiri Forest (child), before play begins ### How often Sometimes ### Graphics card and driver version RTX 4090 24 GB, NVIDIA 615.78.08 ### CPU, RAM and operating system Core i9-13900K, 96 GB RAM, Arch Linux (kernel 7.2.15) ### Changes from the defaults 1920x1080, Custom profile, the game's own upscaler at 100%, frame generation off, no frame cap; run without a window ### longshot_log.txt ```text pull request 66 @ 3fc3c891, start 2 [hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2001.0 ms: core 1: ModuleSystemWorker1 (16); pull request 66 @ 3fc3c891, start 2 [hos bake::ModuleMgr] vcores: bake::ModuleMgr (priority 28) ran without a core after 2000.1 ms: core 1: tera::FileResourceMgr (25); pull request 66 @ 3fc3c891, start 2 [hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.7 ms: core 1: GeneralFormatAsync_ (24); main @ d4a69456, start 5 [hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.4 ms: core 5: ARes Loading 0 (19); pull request 66 @ 3fc3c891, start 8 [hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.5 ms: core 2: BaseProcCreateAndDeleteThread (23); main @ 0c74253d4, start 10 [hos bake::ModuleMgr] vcores: bake::ModuleMgr (priority 28) ran without a core after 2000.9 ms: core 1: ModuleSystemWorker1 (16); main @ 0c74253d4, start 10 [hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2000.8 ms: core 1: ModuleSystemWorker1 (16); main @ 0c74253d4, start 10 [hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.1 ms: core 1: BaseProcCreateAndDeleteThread (23); main @ 0c74253d4, start 10 [hos aglTextureDataMgr::Compaction] vcores: aglTextureDataMgr::Compaction (priority 25) ran without a core after 2000.1 ms: core 1: ModuleSystemWorker1 (16); main @ 0c74253d4, start 10 [hos tera::FileResourceMgr] vcores: tera::FileResourceMgr (priority 25) ran without a core after 2000.5 ms: core 1: ModuleSystemWorker1 (16); ``` ### Screenshots or video None: nothing visible is wrong. ### Before you send it - [ ] The problem is still there on the newest release or nightly. - [x] I searched the open issues for it. - [x] I'm not attaching game files, keys, the game's executable, its .bin caches or saves. Not ticked: seen on main 0c74253d4 built from source on 13 November 2026, not on a downloaded nightly.
Author
Member

More of the same from a second set of runs on the same PC today, 13 November 2026 (RTX 4090, NVIDIA 615.78.08, Core i9-13900K, Arch Linux), taken for the cost measurement of #61: four start-ups into the same Kokiri Forest save, alternating main and that pull request's build, 1920x1080, run without a window. All four wrote the line, every time while the control bridge still reported the game as loading, and never during the 25 seconds that were measured afterwards. All four runs reached play and ended normally, with no fatal or kernel-fault line and no gap over one second between presented frames.

Order Build Lines Game state when written Seconds before the measured phase began
1 main @ d725b363 5 loading 8.2
2 pull request 61 @ 74f8248e 1 loading 6.9
3 main @ d725b363 5 loading 7.5 to 7.7
4 pull request 61 @ 74f8248e 1 loading 10.4

With the ten start-ups above that makes 8 of 14 with at least one line, on three different commits of main and two branches. In these four the core's holder is named as BaseProcCreateAndDeleteThread (6), ModuleSystemWorker1 (2), Presentation Thread (1), BaseProcExecutor1 (1), aal::LowPrioWorkerThread (1), Resource Memory (1).

I would not read anything into 5 lines on main against 1 on the other build: two starts each, and the first set had the counts the other way round between builds. Still no cause and no effect on play shown.

main @ d725b363, start 1
[hos bake::ModuleMgr] vcores: bake::ModuleMgr (priority 28) ran without a core after 2001.0 ms: core 1: Presentation Thread (17);
main @ d725b363, start 1
[hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2000.0 ms: core 1: BaseProcExecutor1 (16);
main @ d725b363, start 1
[hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.0 ms: core 1: ModuleSystemWorker1 (16);
main @ d725b363, start 1
[hos tera::FileResourceMgr] vcores: tera::FileResourceMgr (priority 25) ran without a core after 2000.5 ms: core 1: aal::LowPrioWorkerThread (17);
main @ d725b363, start 1
[hos aglTextureDataMgr::Compaction] vcores: aglTextureDataMgr::Compaction (priority 25) ran without a core after 2000.2 ms: core 1: Resource Memory (21);
pull request 61 @ 74f8248e, start 2
[hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.6 ms: core 5: BaseProcCreateAndDeleteThread (23);
main @ d725b363, start 3
[hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2000.6 ms: core 1: BaseProcCreateAndDeleteThread (23);
main @ d725b363, start 3
[hos bake::ModuleMgr] vcores: bake::ModuleMgr (priority 28) ran without a core after 2001.0 ms: core 1: BaseProcCreateAndDeleteThread (23);
main @ d725b363, start 3
[hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.1 ms: core 1: BaseProcCreateAndDeleteThread (23);
main @ d725b363, start 3
[hos tera::FileResourceMgr] vcores: tera::FileResourceMgr (priority 25) ran without a core after 2000.4 ms: core 1: BaseProcCreateAndDeleteThread (23);
main @ d725b363, start 3
[hos aglTextureDataMgr::Compaction] vcores: aglTextureDataMgr::Compaction (priority 25) ran without a core after 2000.5 ms: core 1: ModuleSystemWorker1 (16);
pull request 61 @ 74f8248e, start 4
[hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2000.2 ms: core 1: BaseProcCreateAndDeleteThread (23);
More of the same from a second set of runs on the same PC today, 13 November 2026 (RTX 4090, NVIDIA 615.78.08, Core i9-13900K, Arch Linux), taken for the cost measurement of https://git.magicbean.dev/MagicBeanDev/Longshot/pulls/61: four start-ups into the same Kokiri Forest save, alternating main and that pull request's build, 1920x1080, run without a window. All four wrote the line, every time while the control bridge still reported the game as loading, and never during the 25 seconds that were measured afterwards. All four runs reached play and ended normally, with no fatal or kernel-fault line and no gap over one second between presented frames. | Order | Build | Lines | Game state when written | Seconds before the measured phase began | |---|---|---:|---|---| | 1 | main @ d725b363 | 5 | loading | 8.2 | | 2 | pull request 61 @ 74f8248e | 1 | loading | 6.9 | | 3 | main @ d725b363 | 5 | loading | 7.5 to 7.7 | | 4 | pull request 61 @ 74f8248e | 1 | loading | 10.4 | With the ten start-ups above that makes 8 of 14 with at least one line, on three different commits of main and two branches. In these four the core's holder is named as `BaseProcCreateAndDeleteThread` (6), `ModuleSystemWorker1` (2), `Presentation Thread` (1), `BaseProcExecutor1` (1), `aal::LowPrioWorkerThread` (1), `Resource Memory` (1). I would not read anything into 5 lines on main against 1 on the other build: two starts each, and the first set had the counts the other way round between builds. Still no cause and no effect on play shown. ```text main @ d725b363, start 1 [hos bake::ModuleMgr] vcores: bake::ModuleMgr (priority 28) ran without a core after 2001.0 ms: core 1: Presentation Thread (17); main @ d725b363, start 1 [hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2000.0 ms: core 1: BaseProcExecutor1 (16); main @ d725b363, start 1 [hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.0 ms: core 1: ModuleSystemWorker1 (16); main @ d725b363, start 1 [hos tera::FileResourceMgr] vcores: tera::FileResourceMgr (priority 25) ran without a core after 2000.5 ms: core 1: aal::LowPrioWorkerThread (17); main @ d725b363, start 1 [hos aglTextureDataMgr::Compaction] vcores: aglTextureDataMgr::Compaction (priority 25) ran without a core after 2000.2 ms: core 1: Resource Memory (21); pull request 61 @ 74f8248e, start 2 [hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.6 ms: core 5: BaseProcCreateAndDeleteThread (23); main @ d725b363, start 3 [hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2000.6 ms: core 1: BaseProcCreateAndDeleteThread (23); main @ d725b363, start 3 [hos bake::ModuleMgr] vcores: bake::ModuleMgr (priority 28) ran without a core after 2001.0 ms: core 1: BaseProcCreateAndDeleteThread (23); main @ d725b363, start 3 [hos PreActorModelCompose] vcores: PreActorModelCompose (priority 26) ran without a core after 2000.1 ms: core 1: BaseProcCreateAndDeleteThread (23); main @ d725b363, start 3 [hos tera::FileResourceMgr] vcores: tera::FileResourceMgr (priority 25) ran without a core after 2000.4 ms: core 1: BaseProcCreateAndDeleteThread (23); main @ d725b363, start 3 [hos aglTextureDataMgr::Compaction] vcores: aglTextureDataMgr::Compaction (priority 25) ran without a core after 2000.5 ms: core 1: ModuleSystemWorker1 (16); pull request 61 @ 74f8248e, start 4 [hos BakeProbe] vcores: BakeProbe (priority 28) ran without a core after 2000.2 ms: core 1: BaseProcCreateAndDeleteThread (23); ```
Author
Member

I took this one and have a cause and a fix ready.

Cause. The waiting threads are pinned to one core (PreActorModelCompose, BakeProbe, bake::ModuleMgr, tera::FileResourceMgr, aglTextureDataMgr::Compaction, PlayReporter) and have a lower priority than everything that holds it. A waiter asks a holder to give the core up only when the holder is worse than itself, and every release goes to the best waiter, so while the load runs the core changes hands between better threads and the pinned thread is never first. I counted it with a diagnostic build of main that logs every take of the waiter's core during a long wait. In 12 starts (the same Kokiri Forest save, windowless, RTX 4090): 15 escapes in 5 starts, the core taken 42,593 to 53,473 times during each 2 s wait (about 21,000 to 27,000 times a second, mostly by priority 16 and 23 threads), the holder at the escape having held it for 24 to 168 microseconds, and no core kept by one thread for the wait. A further 11 waits of 1.2 to 2.0 s ended by themselves the same way. On the lines posted here, the holder is better than the waiter in 22 of 22; in the log on #91 (an RX 9070 XT, 16 GB of RAM, Linux) it is 44 of 44, and its line vcores: 1352 takes, 866 waits (mean 64434 us, longest 2001.0 ms), 184 kicks, 172 yields, 13 escapes in 5 s is the same fault (that PC was under memory pressure at 1.7 frames a second, so I read it as the same kind of line, not the same cause of the stall).

Fix. A waiter that has waited 1 s (HOS_VCORE_STARVE_US, 0 turns it off) goes first at the next release of a core it may use and asks the worst holder to give the core up, whatever its priority. The 2 s escape stays as the deadlock breaker. On main in ten plain starts, 3 had escapes (8 lines). With the fix against the same build with HOS_VCORE_STARVE_US=0, ten starts each, interleaved: 0 of 10 starts with an escape against 4 of 10 (7 lines), the longest core wait in every start 1.002 s at most against 2.0 s, and the time to play unchanged (median 43.1 and 43.2 s, ordinary runs). The count of starts alone is weak (p = 0.087); the cap on the wait and the take counts above are the evidence. Not tested: Windows, other GPUs and CPUs, play after loading.

The change is a game-free test (fails on main, passes with the fix) and about 30 added lines in host/hos_thread.c; it touches the same block as #327 and #249, which would need a rebase on whichever merges second. The pull request: #594 (work in progress until it is built for Windows and Linux on current main).

I took this one and have a cause and a fix ready. **Cause.** The waiting threads are pinned to one core (PreActorModelCompose, BakeProbe, bake::ModuleMgr, tera::FileResourceMgr, aglTextureDataMgr::Compaction, PlayReporter) and have a lower priority than everything that holds it. A waiter asks a holder to give the core up only when the holder is worse than itself, and every release goes to the best waiter, so while the load runs the core changes hands between better threads and the pinned thread is never first. I counted it with a diagnostic build of main that logs every take of the waiter's core during a long wait. In 12 starts (the same Kokiri Forest save, windowless, RTX 4090): 15 escapes in 5 starts, the core taken 42,593 to 53,473 times during each 2 s wait (about 21,000 to 27,000 times a second, mostly by priority 16 and 23 threads), the holder at the escape having held it for 24 to 168 microseconds, and no core kept by one thread for the wait. A further 11 waits of 1.2 to 2.0 s ended by themselves the same way. On the lines posted here, the holder is better than the waiter in 22 of 22; in the log on https://git.magicbean.dev/MagicBeanDev/Longshot/issues/91 (an RX 9070 XT, 16 GB of RAM, Linux) it is 44 of 44, and its line `vcores: 1352 takes, 866 waits (mean 64434 us, longest 2001.0 ms), 184 kicks, 172 yields, 13 escapes in 5 s` is the same fault (that PC was under memory pressure at 1.7 frames a second, so I read it as the same kind of line, not the same cause of the stall). **Fix.** A waiter that has waited 1 s (`HOS_VCORE_STARVE_US`, 0 turns it off) goes first at the next release of a core it may use and asks the worst holder to give the core up, whatever its priority. The 2 s escape stays as the deadlock breaker. On main in ten plain starts, 3 had escapes (8 lines). With the fix against the same build with `HOS_VCORE_STARVE_US=0`, ten starts each, interleaved: 0 of 10 starts with an escape against 4 of 10 (7 lines), the longest core wait in every start 1.002 s at most against 2.0 s, and the time to play unchanged (median 43.1 and 43.2 s, ordinary runs). The count of starts alone is weak (p = 0.087); the cap on the wait and the take counts above are the evidence. Not tested: Windows, other GPUs and CPUs, play after loading. The change is a game-free test (fails on main, passes with the fix) and about 30 added lines in `host/hos_thread.c`; it touches the same block as https://git.magicbean.dev/MagicBeanDev/Longshot/pulls/327 and https://git.magicbean.dev/MagicBeanDev/Longshot/pulls/249, which would need a rebase on whichever merges second. The pull request: https://git.magicbean.dev/MagicBeanDev/Longshot/pulls/594 (work in progress until it is built for Windows and Linux on current main).
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
MagicBeanDev/Longshot#262
No description provided.