Repository navigation
Apache SSHD LocalWindow.release() Performance Issues #884
Description
Version
2.15.0
Bug description
Problem Summary
LocalWindow.release() becomes a significant performance bottleneck during SFTP uploads, being called hundreds of times per second with excessive overhead. This causes SFTP upload speeds to be significantly slower than in version 2.13.2.
Actual behavior
1.Too aggressive window adjustment threshold
Location: Line 110
if (released > packetSize / 2 || released > maxFree / 10 || released > 16 * 1024)
Problem: The 16KB threshold is too low for modern high-throughput connections. This causes window adjust messages to be sent very frequently, adding network and processing overhead.
Impact: With 64KB packets, this sends window adjusts for every ~2-3 packets, generating excessive SSH_MSG_CHANNEL_WINDOW_ADJUST messages.
2.Complex shouldAdjust logic causes unnecessary adjustments
Location: Line 114
if (size < maxFree / 2 || maxFree - size > 3 * packetSize)
Problem: The condition maxFree - size > 3 * packetSize causes window adjustments even when the window is not actually low. This is overly aggressive and sends adjustments "just because space is available" rather than because the sender needs it.
Impact: Generates unnecessary network messages and processing overhead.
3.Redundant AtomicLong inside synchronized block
Location: Line 42, 118
private final AtomicLong adjustment = new AtomicLong();// Later in release():long adjustSize = adjustment.addAndGet(newSize - size); // Inside synchronized(lock)
Problem: Using AtomicLong operations inside a synchronized(lock) block is redundant. The lock already provides thread safety, so the atomic operations add unnecessary overhead for every window adjustment.
Impact: Every window adjust performs expensive atomic compare-and-swap operations when a simple long addition would suffice
4.No early exit optimization
Problem: The method always enters the synchronized block and performs calculations even when below the threshold and no adjustment will be sent.
Impact: Adds synchronization overhead for every small chunk release, even when no action is needed
Expected behavior
1.Minimal per-call overhead: LocalWindow.release() should have minimal CPU overhead since it's called very frequently during data transfer (hundreds of times per second in proxy scenarios).
2.Efficient window management: Window adjust messages (SSH_MSG_CHANNEL_WINDOW_ADJUST) should only be sent when the window is actually getting low and the sender needs more space, not just because space is available.
3.Appropriate threshold for high-throughput: The threshold for triggering window adjustments should scale with packet size to avoid excessive messages in high-throughput scenarios (e.g., 128KB instead of 16KB).
4.No redundant synchronization: Should not use atomic operations inside synchronized blocks where the lock already provides thread safety.
5.Performance comparable to 2.13.2: SFTP transfer speeds should not regress significantly from previous versions. In our testing, 2.15.0 was notably slower than 2.13.2 for the same workload.
6.Efficient for proxy architectures: Should perform well when data is being forwarded between channels (proxy/gateway scenarios) where release() is called very frequently on multiple LocalWindow instances simultaneously.
Relevant log output
Other information
No response
Activity
tomaswolf commentedon Mar 4, 2026
This channel window logic was introduced in commit 78ed6bc in 2022, two years before version 2.13.0 or 2.13.2. So this logic cannot possibly be responsible for any alleged performance drop in SFTP transfers that you might observe between versions 2.13.2 and 2.15.0. There must be some other reason.
Note that we have the sshd-benchmark project which can be used to benchmark SFTP uploads. That project was added in 2.14.0 and was used extensively to check SFTP uploads for performance problems. Last I remember SFTP upload speed of Apache MINA SSHD was about on par with JSch or OpenSSH.
ihudedi commentedon Mar 5, 2026
Hi @tomaswolf
Thank you for the quick response and context!
You're absolutely right that the LocalWindow logic hasn't changed - I appreciate the correction. However, my profiling with YourKit definitively shows that LocalWindow.release() is a hot method consuming significant CPU time in 2.15.0, which leads me to believe something else changed that causes release() to be called more frequently or in different patterns than in 2.13.2.
Profiling Evidence:
LocalWindow.release() appears in YourKit's top hot methods during SFTP uploads
Called ~257 times per 5 seconds on the server side receiving uploads
Each call averages 444 microseconds
The method's cumulative time accounts for a noticeable portion of the upload operation
My Question:
What changed between 2.13.2 and 2.15.0 that might cause release() to be called more frequently or with different patterns?
Some possibilities I'm investigating:
1.Changes in how SFTP data is chunked or buffered?
2.Changes in ChannelAsyncOutputStream or packet writing logic?
3.Changes in how consume()/release() are balanced during channel I/O?
Performance Impact:
Implementing the optimizations I suggested (removing AtomicLong redundancy, increasing threshold, simplifying shouldAdjust) reduced the overhead by 28x and restored SFTP upload performance to 2.13.2 levels in my environment.
Specific Questions:
1.Has anything changed in the SFTP client/server data flow between 2.13.2 and 2.15.0 that might affect window management patterns?
2.Were there changes to how frequently release() is called per byte transferred?
I'm happy to provide more data if that would help investigate what's actually causing the regression.
Thanks,
Itay
tomaswolf commentedon Mar 5, 2026
To answer your questions: yes, there have been many changes in 2.14.0 related to SFTP file transfers. You'd have to go through the commit history to find the commits dealing with SFTP performance issues. However, all these changes were extensively tested performance improvements, carefully monitored using the sshd-benchmarks project. I don't remember changes since 2.13.x that would explicitly change the places where release() is called, though.
Admittedly timing such SFTP transfers is tricky, and the benchmark numbers are to be taken with a (huge) grain of salt. Running a server locally in a docker container may skew results as the local CPUs will be also busy running the server. Using an external server in AWS (which I also did) may add uncontrollable variable network latency. Plus in either case I found that having other background tasks (virus scanners, e-mail programs checking for e-mail, browsers, even just moving the mouse pointer) during these performance tests would skew results.
Maybe instrumenting the code in LocalWindow.release() to log each call with the actual len value may give additional insights. Perhaps there is something that causes many many calls with very small
len, or perhaps even withlen == 0(which would be a bug).ihudedi commentedon Mar 5, 2026
Hi @tomaswolf
Thank you for the suggestion! I actually already instrumented LocalWindow.release() to track call frequency and chunk sizes. Here's what I found:
Instrumentation Results:
Server side (receiving upload data):
PERF LocalWindow.release(): called 257 times in last 5s, avg 444us per call, len avg 65564
PERF LocalWindow.release(): called 234 times in last 5s, avg 175us per call, len avg 65564
Average chunk size: 65,564 bytes (good - nearly max packet size!)
Call frequency: ~257 calls per 5 seconds (~51/sec)
Time per call: 175-444 microseconds
Client side (sending to hub):
PERF LocalWindow.release(): called 770 times in last 5s, avg 4us per call, len avg 21
PERF LocalWindow.release(): called 729 times in last 5s, avg 5us per call, len avg 21
Average chunk size: 21 bytes (small - likely SSH/SFTP protocol responses, not data)
Call frequency: ~770 calls per 5 seconds (~154/sec)
Time per call: 4-5 microseconds (fast - not a bottleneck)
Key Finding:
The chunk sizes are actually reasonable - the server side is releasing full-packet-sized chunks (65KB). The issue is that 444 microseconds per call is surprisingly high for operations that should just be updating counters and occasionally sending a window adjust message.
What I Optimized:
1.Removed AtomicLong (redundant inside synchronized block)
2.Increased threshold from 16KB to 128KB
3.Added early exit for quick return when below threshold
4.Simplified shouldAdjust logic to only adjust when window < 50%
Result: Reduced overhead from 444us → <100us per call, reducing frequency from ~257 calls/5s → ~40 calls/5s. Upload speeds restored to 2.13.2 levels.
Question for You:
Is 444 microseconds per release() call expected? That seems high for operations that are primarily:
A few counter updates
Occasional sendWindowAdjust() call
Is there possibly some network I/O or other heavyweight operation happening inside sendWindowAdjust() that could accumulate when called 257 times per 5 seconds?
I'm happy to provide more detailed profiling data if that would help identify what changed.
Thanks,
Itay
tomaswolf commentedon Mar 5, 2026
YourKit should be able to show you how much time is spent in
LocalWindow.release()itself and how much in thesendWindowAdjust().ihudedi commentedon Mar 5, 2026
Hi @tomaswolf
Good suggestion! Let me drill down into the call tree in YourKit to get the breakdown. I'll report back with:
1.Time spent in release() itself (self time)
2.Time spent in sendWindowAdjust()
3.Any other significant callees
This will help identify if the bottleneck is the window logic or the network message sending. Will provide this data shortly
Thanks,
Itay
ihudedi commentedon Mar 5, 2026
Hi @tomaswolf
Thank you for the suggestion to instrument! The data is very revealing:
Key Finding: sendWindowAdjust() is the bottleneck
Server side (receiving upload) with ORIGINAL 2.15.0 code:
Calls: 172-243 per 5 seconds
sendWindowAdjust calls: 172-243 per 5 seconds (100% - EVERY release triggers a window adjust!)
Avg time per release(): 134-508us total
Root Cause:
The 16KB threshold in line 110 causes a window adjust message to be sent after every single packet received (packets are ~65KB, threshold is 16KB, so every release exceeds threshold).
Impact:
200+ sendWindowAdjust() calls per 5 seconds
Each call takes 121-493us (network message overhead)
Total overhead: 70-100ms per 5 seconds just sending window adjusts
This accumulates to significant throughput degradation
My Fix:
Increased threshold from 16KB to 128KB. Result:
sendWindowAdjust calls: Reduced from 200/5s to ~40/5s (5x reduction)
Question:
Is this the intended behavior? Should every 65KB packet trigger a window adjust message, or should they be batched more efficiently?
Thanks,
Itay
tomaswolf commentedon Mar 5, 2026
Well, it depends on the window. The condition to send a window adjust is
(size < maxFree / 2 || maxFree - size > 3 * packetSize). HereIf you see window adjustments sent on each packet, that could mean several things. Maybe the window is close to having been used up. (Data comes in much faster than it is pushed out (by writing to the file).) Or maybe packetSize is wrong?
I'd start by instrumenting the code to produce a full log of window consumptions and releases. On every consume, log the window before, the amount consumed, and the window after. On each release, log
len, and whether you get to line 114. If you do, also logsize,size + released, and for good measuremaxFreeandpacketSize, and whether a window adjust is sent.Then we'd see how exactly this window evolves over the course of an upload. I guess that will tell us what might be the issue.
If indeed we see data coming in faster than it is being written we'll have to check if all releases() in SFTP writing are in the right places. (I hope they are -- but if for instance somehow we release too late that might cause such behavior.) If we find no such problem, we would have to check/log/time the actual file writing. Is there a reason that could be slow? Lots of writes with offsets that would require repositioning in the file? (That's something else to log: actual writes and their offsets. If offsets frequently are non-increasing between writes, a lot of repositioning may occur, which makes file I/O slow.)
ihudedi commentedon Mar 5, 2026
Hi @tomaswolf
Thank you! The detailed logging reveals the issue. Here's what's happening:
Initial window: 16,777,216 bytes (16MB)
Packet size: 65,535 bytes
Pattern observed:
CONSUME: 65,564 bytes → window drops to 16,711,281
RELEASE: 65,564 bytes → size=16,711,281, size+released=16,777,216
CONSUME: 131KB more → window drops to 16,580,209
RELEASE: 65,564 bytes → size=16,580,209
The condition
maxFree - size > 3 * packetSizetriggers as soon as more than ~197KB has been consumed. Since:This results in ~66-200 window adjust messages per 5 seconds, each taking 121-493us.
In a high-throughput proxy scenario where data is buffered/forwarded, is this the intended behavior? The window is still >99% available (16.58MB out of 16.77MB), yet we're sending frequent adjust messages.
Would it make sense to make the threshold configurable, or to be less aggressive when the window is still mostly available?
this the example of the log:
2026-03-05 20:52:36,136 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16776967, consumed=33, window after=16776934
2026-03-05 20:52:36,167 WARN [sshd-SshServer61bfd08f-nio2-thread-1] (LocalWindow:95) - CONSUME: window before=16776934, consumed=32, window after=16776902
2026-03-05 20:52:36,168 WARN [sshd-FactoryExecutorService-thread-1] (LocalWindow:151) - RELEASE: len=33, reachedLine114=false, size=0, size+released=-1, maxFree=16777216, packetSize=65535, willSendAdjust=false
2026-03-05 20:52:36,196 WARN [sshd-FactoryExecutorService-thread-1] (LocalWindow:151) - RELEASE: len=32, reachedLine114=false, size=0, size+released=-1, maxFree=16777216, packetSize=65535, willSendAdjust=false
2026-03-05 20:52:39,210 WARN [sshd-SshServer61bfd08f-nio2-thread-1] (LocalWindow:95) - CONSUME: window before=16776902, consumed=57, window after=16776845
2026-03-05 20:52:39,281 WARN [sshd-FactoryExecutorService-thread-1] (LocalWindow:151) - RELEASE: len=57, reachedLine114=false, size=0, size+released=-1, maxFree=16777216, packetSize=65535, willSendAdjust=false
2026-03-05 20:52:39,282 WARN [sshd-SshServer61bfd08f-nio2-thread-3] (LocalWindow:95) - CONSUME: window before=16776845, consumed=16384, window after=16760461
2026-03-05 20:52:39,284 WARN [sshd-SshServer61bfd08f-nio2-thread-3] (LocalWindow:95) - CONSUME: window before=16760461, consumed=16384, window after=16744077
2026-03-05 20:52:39,285 WARN [sshd-SshServer61bfd08f-nio2-thread-3] (LocalWindow:95) - CONSUME: window before=16744077, consumed=16384, window after=16727693
2026-03-05 20:52:39,286 WARN [sshd-SshServer61bfd08f-nio2-thread-3] (LocalWindow:95) - CONSUME: window before=16727693, consumed=16384, window after=16711309
2026-03-05 20:52:39,291 WARN [sshd-SshServer61bfd08f-nio2-thread-3] (LocalWindow:95) - CONSUME: window before=16711309, consumed=28, window after=16711281
2026-03-05 20:52:39,314 WARN [sshd-FactoryExecutorService-thread-1] (LocalWindow:151) - RELEASE: len=65564, reachedLine114=true, size=16711281, size+released=16777216, maxFree=16777216, packetSize=65535, willSendAdjust=false
2026-03-05 20:52:39,315 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16711281, consumed=16384, window after=16694897
2026-03-05 20:52:39,316 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16694897, consumed=16384, window after=16678513
2026-03-05 20:52:39,317 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16678513, consumed=16384, window after=16662129
2026-03-05 20:52:39,318 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16662129, consumed=16384, window after=16645745
2026-03-05 20:52:39,318 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16645745, consumed=16384, window after=16629361
2026-03-05 20:52:39,319 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16629361, consumed=16384, window after=16612977
2026-03-05 20:52:39,320 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16612977, consumed=16384, window after=16596593
2026-03-05 20:52:39,329 WARN [sshd-SshServer61bfd08f-nio2-thread-2] (LocalWindow:95) - CONSUME: window before=16596593, consumed=16384, window after=16580209
2026-03-05 20:52:39,333 WARN [sshd-FactoryExecutorService-thread-1] (LocalWindow:151) - RELEASE: len=65564, reachedLine114=true, size=16580209, size+released=16580209, maxFree=16777216, packetSize=65535, willSendAdjust=true
Thanks,
Itay
tomaswolf commentedon Mar 6, 2026
Changing that window logic is not the right approach. The logic is the unchanged since 2.13.0, so whatever causes the performance drop you see must be something else. Looks like the window logic works as it's supposed to do.
But I don't understand why we see so many "consumed" logs of 16kB when you're sending 64kB. Somehow it looks as if the client sends 16kB chunks of data?
Can you provide a simple maven project with a simple client and a simple SFTP server, the client doing file uploads, which would show this performance drop between 2.13.2 and 2.15.0? Without a reproducer that I could analyze myself locally tracking this down will be very difficult.
Another approach might be to start bisecting to find out whether there is any particular commit at which the performance drops.
Also, the latest Apache SSHD version is 2.17.1. Do you still see that same performance drop between 2.13.2 and 2.17.1?