[Bug 57289] New: Performance degradation after LFH
https://bugs.winehq.org/show_bug.cgi?id=57289 Bug ID: 57289 Summary: Performance degradation after LFH Product: Wine Version: 9.0 Hardware: x86-64 OS: Linux Status: UNCONFIRMED Severity: normal Priority: P2 Component: ntdll Assignee: wine-bugs(a)winehq.org Reporter: rikul(a)inbox.ru Distribution: --- In one of my applications, there is a performance degradation in a specific scenario after LFH. I still can’t localize the problem to send you the block of code where the tool experiences performance issues. Are you aware of any known issues related to this? The main part of the degradation occurs in the LFH group release section. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=57289 Fabian Maurer <dark.shadow4(a)web.de> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |dark.shadow4(a)web.de --- Comment #1 from Fabian Maurer <dark.shadow4(a)web.de> --- LFH meaning "low fragmentation heap"? -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=57289 --- Comment #2 from BugSeeker <rikul(a)inbox.ru> --- Yes, LFH is Low Fragmentation Heap. In that scenario, closing the group_release (which has the memory leak) restores the performance numbers to their previous, better levels. Are you familiar with this? Are there any known issues? -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=57289 --- Comment #3 from BugSeeker <rikul(a)inbox.ru> --- I mean closing the call to the group_release() function for the experiment to identify where the performance is lacking -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
https://bugs.winehq.org/show_bug.cgi?id=57289 --- Comment #4 from Fabian Maurer <dark.shadow4(a)web.de> --- Sorry, I'm not familiar with this, just looking for clarification. Without being able to reproduce and profile that could be difficult. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
http://bugs.winehq.org/show_bug.cgi?id=57289 NishinoAkifumi <niakhm05@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |niakhm05@gmail.com --- Comment #5 from NishinoAkifumi <niakhm05@gmail.com> --- We hit what looks like the same issue on Wine 11.0 and have a full profile, an analysis of the mechanism and a one-line workaround, so here it is in the hope that it makes this bug reproducible. It matches comment 2: in our case too, the whole degradation is the release / re-allocation of fully freed LFH groups, and once groups are no longer handed back to the backend heap the degradation is gone. ### Environment - Wine 11.0 (WineHQ stable package for Debian bookworm), 64-bit prefix, running in a Docker container on Ubuntu 24.04 (kernel 7.0), Intel Core Ultra 7 265K. The relevant code in dlls/ntdll/heap.c is unchanged between 11.0 and current git. - Application: DCS World Dedicated Server 2.9.29.27468 (`DCS_server.exe --server --norender`) with the DCS Olympus 2.0.5 mod. Olympus runs inside the DCS process (olympus.dll / core.dll / luatools.dll / cpprest_2_10.dll) and, every 50 ms, converts a Lua table describing the units into a cpprestsdk `json::value` document, serves it, and discards it. That is a few thousand 48-byte `json::value` nodes allocated and freed per cycle on the ucrtbase CRT heap, from the simulation thread. ### Symptom Right after start the server runs at 117 FPS with the process at ~42 % of one core (idle mission, 0 players). The simulation thread's CPU usage then grows roughly linearly, about +25 percentage points per hour, until it saturates the core after 2.5-3 hours and the server FPS collapses to ~28. Restarting the process resets it and the same ramp repeats. Player count, mission content and everything else were ruled out: the ramp is identical with 0 players and does not happen at all with Olympus disabled (flat at ~44 % for 6 hours). # one run, 0 players throughout: process CPU % / server FPS vs. uptime uptime 10min 30min 60min 90min 120min 150min 180min 240min CPU % 42 51 59 72 81 98 108 108 FPS 116 107 95 73 64 37 29 29 The same server + Olympus combination is widely run on Windows and this growth is not reported there. We have not measured it on Windows ourselves. ### Profile (perf on the simulation thread, at saturation) perf record -F 499 -t <main tid> (DSO level; PE modules have no symbols under perf) 85.40% ntdll.dll <- 77% of it in the 5-instruction loop below (ntdll.dll+0x4f500) 9.18% [JIT] <- the game's own PE modules (anonymous mappings) 3.09% ntdll.so 0.56% ucrtbase.dll The hot loop is the first-fit walk of `find_free_block()` inlined into `heap_allocate_block()` (dlls/ntdll/heap.c): 17004f500: movzx edx,BYTE PTR [rbx-0x1] ; block flags 17004f504: cmp dl,0x3 ; BLOCK_FLAG_FREE_LINK -> skip list head 17004f50c: movzx eax,WORD PTR [rbx-0x8] ; block_size 17004f515: shl eax,0x4 17004f518: cmp rax,r13 ; >= requested block size ? 17004f51b: jae found 17004f521: mov rbx,QWORD PTR [rbx] ; next free entry 17004f529: cmp rbx,r8 ; end of list ? 17004f52c: jne 17004f500 Sampling the registers inside that loop (`perf record --user-regs=R13,R12`, 5,160 samples): the requested block size (r13) is 0x5f0 in 100 % of the samples and there is a single heap handle (the CRT heap of ucrtbase). The caller, taken with LBR call graphs (`--call-graph lbr`), is `RtlAllocateHeap+0x725`. Disassembling it shows it is not a regular allocation but the inlined `group_allocate()` of the LFH front end: 17001b5e0: mov rax,r12 ; r12 = 0x30 (bin block size, 48-byte blocks) 17001b5e3: shl rax,0x5 17001b5e7: sub rax,r12 ; rax = 31 * 0x30 (GROUP_BLOCK_COUNT) 17001b5ea: lea r8,[r15+rax*1+0x27] 17001b5f6: and r8,0xfffffffffffffff0 ; = 0x5f0, the group block size ... 17001b655: call heap_allocate_block ; 100 % of the walk samples come from here So 0x5f0 = 1,520 bytes is the size of one LFH group for the 48-byte bin (31 blocks + header), and the time is spent allocating LFH *groups* from the backend heap, over and over. Reading `struct heap` from the live process confirmed that the bins involved are LFH-enabled (`enabled = 1`) and that practically no regular allocation of the application goes through the backend any more; the backend traffic on this heap is essentially group blocks. ### Analysis (wine-11.0 dlls/ntdll/heap.c) 1. `heap_release_bin_group()`: when a group becomes fully free, it is kept in the thread's affinity slot (1 group), otherwise pushed on the bin's shared SList only while `RtlQueryDepthSList(&bin->groups) <= ARRAY_SIZE(affinity_mapping)` (32), otherwise `group_release()` returns it to the backend heap with `heap_free_block()`. 2. Olympus frees a few thousand 48-byte nodes at the end of every 50 ms cycle, which empties on the order of a hundred groups at once. Everything beyond the ~33 cached groups is released to the backend, and at the start of the next cycle `heap_acquire_bin_group()` finds the SList empty again and calls `group_allocate()` -> `heap_allocate_block(0x5f0)` for each of them. That is on the order of 10^3 group allocations per second through the backend, forever. 3. `find_free_block()` starts at the free list for the size class of 0x5f0, which with the log-linear bucketing is [0x500, 0x600), and walks forward. Every free block in that bucket that is smaller than 0x5f0 (sizes 0x500-0x5e0) is visited and skipped on every single group allocation. Such blocks can never be consumed: no application request in that size range reaches the backend once the LFH serves it, and the only backend requests are the (fixed, larger) group sizes and large blocks. They are produced by `split_block()` remainders and by partial coalescing of released groups with neighbouring free space, so their number only grows with uptime, and with it the length of every walk. (We did not dump the free lists in a stock run; this part is inferred from the code and from the observations that the walk time grows linearly with uptime and disappears completely once groups stop being released.) ### Workaround we are running Keeping the fully freed groups in the bin instead of releasing them makes the problem disappear entirely (patch attached): --- a/dlls/ntdll/heap.c +++ b/dlls/ntdll/heap.c @@ -1885,7 +1885,7 @@ static NTSTATUS heap_release_bin_group( struct heap *heap, ULONG flags, struct bin *bin, struct group *group ) return STATUS_SUCCESS; /* try re-using the block group instead of releasing it */ - if (RtlQueryDepthSList( &bin->groups ) <= ARRAY_SIZE(affinity_mapping)) + if (RtlQueryDepthSList( &bin->groups ) <= 0x1000) { RtlInterlockedPushEntrySList( &bin->groups, &group->entry ); return STATUS_SUCCESS; (0x1000 groups of 0x5f0 bytes is at most ~6 MB retained per bin for the 48-byte bin; a real fix probably wants something smarter than a constant, e.g. a cap derived from the bin's peak usage, or a way for `group_allocate()` to avoid the first-fit walk altogether. Another option would be to start the walk from the next free list so that every visited block is guaranteed to fit, at the cost of a little more fragmentation.) Results with the patched ntdll.dll (PE side only, rebuilt from the wine-11.0 tarball with mingw; the unix ntdll.so is stock), same server, same mission, Olympus at its default 50 ms cadence, 0 players: - 4 min after start: ntdll.dll share of the simulation thread 9.6 % (stock at the same point of a run: 40 %; at saturation: 85 %); the free-list walk no longer appears in the profile. - 175 min: process CPU 38.2 %, 117.7 FPS, completely flat (stock: 100 % of a core after 120 min). At 116 min ntdll.dll was 10.9 %, of which heap_allocate_block 1.4 %. - In production since then (about a day and a half at the time of writing, 12-hour restart cycle, up to ~10 players): no ramp in any run. We also tried relaxing `bin_try_enable()` so that every bin is enabled after 0x800 allocations (not only bins below 0x30). That was a wrong first guess (we initially thought a 1,520-byte *application* block size was not getting LFH-enabled); it has no measurable effect on this issue and is not needed for the fix above. ### Reproducer We do not have a small stand-alone reproducer yet. A synthetic loop that allocates and frees 4,000 x 48 bytes + 2,000 x 24 bytes + 50 x 1,512 bytes per cycle for 20,000 cycles runs 11 % faster with the patch but does not show the unbounded growth; the fragmentation in the real process apparently needs many more cycles and the interleaving of other threads' heap traffic. The real-world case is reproducible every time: DCS World dedicated server + DCS Olympus 2.0.5, wait 2-3 hours. Happy to provide the raw perf data, the disassembly, or to test patches. -- Do not reply to this email, post in Bugzilla using the above URL to reply. You are receiving this mail because: You are watching all bug changes.
participants (2)
-
WineHQ Bugzilla -
WineHQ Bugzilla