Skip to content

Commit 4f26228

Browse files
committed
[SPARK-58985][CORE] Fix HistoryServerDiskManager double-counting store size on concurrent release and makeRoom
### What changes were proposed in this pull request? Make the disk usage accounting in `HistoryServerDiskManager` atomic with the store operation it accompanies: - `release()` now performs the whole operation -- removing the app from the `active` map, updating usage accounting, and deleting or re-measuring the store -- under the `active` lock. When the store directory is already gone, it also drops the listing entry so the store is not deducted again later. - `Lease.commit()` now moves the store into place, updates usage accounting, writes the listing entry, and registers the app in the `active` map under the `active` lock, so the store is never on disk without being tracked. A failed rename raises an `IOException` instead of recording a store that is not there. When the previous store directory is already gone but still listed, its listing entry and accounting are dropped before the new store takes its place. - `openStore()` now writes the listing entry under the `active` lock, so a concurrent `release()` cannot leave a listing entry for a deleted store. - `makeRoom()` re-checks each eviction candidate under the `active` lock before deleting it: it skips candidates that became active or that a concurrent `release()` or `commit()` already deleted, and deducts the size the listing holds at that point. The summary log reports the stores actually deleted and the space actually freed, and warns when nothing could be freed. On that log line, `NUM_BYTES_EVICTED` now carries the freed bytes and `NUM_BYTES_TO_FREE` the target, and the store count moves to `NUM_APPS`; consumers of these structured-logging fields should note the change. The lock now covers directory I/O (`sizeOf`, rename, deletion, listing read/write). As a trade-off, `openStore()` from UI requests can block while a concurrent `release()` (e.g., in the `cleanLogs` loop) or `makeRoom()` eviction deletes a store; this is deliberate to keep the accounting accurate. ### Why are the changes needed? `HistoryServerDiskManager` can deduct the same store size twice, driving the committed usage negative and making the History Server throw `IllegalStateException: Disk usage tracker went negative`. The race is longstanding: `release()` updates usage and operates on the store directory outside the `active` lock, `commit()` moves the store into place before registering it, and `makeRoom()` deletes eviction candidates without re-checking, so two paths have been able to deduct the same store since the disk manager was introduced by SPARK-20654 (2.3.0). SPARK-56044 (4.0.3) widened the race. By adding a deduction in `release()` based on the size measured from disk for apps not in the `active` map, a double deduction no longer requires the application to be actively open: - `release(delete = true)` vs `openStore()`: `release()` deducts the measured size and deletes the store, but a concurrent `openStore()` re-registered the app in `active`, so a subsequent `release()` deducts the size again. - `release(delete = true)` vs `commit()`: `commit()` has moved the store into place but not yet registered it, so `release()` deducts the measured size and deletes the store; `commit()` then registers the deleted store, and a subsequent `release()` deducts the size again. - `release(delete = true)` vs `makeRoom()`: both paths deduct the size of the same store. This makes the race reachable in normal History Server operation, e.g. log cleanup calling `release(delete = true)` for an app never opened after a restart while a concurrent UI request opens, loads, or evicts the same store. The fix also closes two concurrent `makeRoom()` calls evicting the same store twice. This crash was observed on a production History Server (4.1-based build), in the periodic log cleanup path: ``` java.lang.IllegalStateException: Disk usage tracker went negative (now = -118595158, delta = -151974353) at o.a.s.deploy.history.HistoryServerDiskManager.updateUsage(HistoryServerDiskManager.scala:285) at o.a.s.deploy.history.HistoryServerDiskManager.release(HistoryServerDiskManager.scala:186) at o.a.s.deploy.history.FsHistoryProvider.cleanAppData(FsHistoryProvider.scala:746) at o.a.s.deploy.history.FsHistoryProvider.deleteAttemptLogs(FsHistoryProvider.scala:1132) at o.a.s.deploy.history.FsHistoryProvider.cleanLogs(FsHistoryProvider.scala:1063) at o.a.s.deploy.history.FsHistoryProvider.$anonfun$startPolling$4(FsHistoryProvider.scala:305) ``` ### Does this PR introduce _any_ user-facing change? No. ### How was this patch tested? Added five tests to `HistoryServerDiskManagerSuite`. The three race tests (`release with delete is atomic with openStore`, `makeRoom is atomic with release`, `commit is atomic with release`) park one operation mid-way, run the competing operation on another thread, and let the parked one proceed once the competing thread has finished or blocked on the lock, so none relies on a fixed wait. Each fails on the pre-fix code, the first with `openStore()` handing out a store being deleted, the other two with `IllegalStateException: Disk usage tracker went negative`. `makeRoom deducts a store deleted out of band` and `commit deducts a store deleted out of band` pin the accounting for stores removed outside the History Server. ### Was this patch authored or co-authored using generative AI tooling? Generated-by: Qwen 3.8 Max Closes #58312 from pan3793/SPARK-58985. Authored-by: Cheng Pan <pan3793@gmail.com> Signed-off-by: Cheng Pan <chengpan@apache.org> (cherry picked from commit ff9d3e3) Signed-off-by: Cheng Pan <chengpan@apache.org>
1 parent 32f7e10 commit 4f26228

2 files changed

Lines changed: 255 additions & 59 deletions

File tree

core/src/main/scala/org/apache/spark/deploy/history/HistoryServerDiskManager.scala

Lines changed: 92 additions & 55 deletions
Original file line numberDiff line numberDiff line change
@@ -17,7 +17,7 @@
1717

1818
package org.apache.spark.deploy.history
1919

20-
import java.io.File
20+
import java.io.{File, IOException}
2121
import java.util.concurrent.atomic.AtomicLong
2222

2323
import scala.collection.mutable.{HashMap, ListBuffer}
@@ -67,6 +67,8 @@ private class HistoryServerDiskManager(
6767
private val maxUsage = conf.get(MAX_LOCAL_DISK_USAGE)
6868
private val currentUsage = new AtomicLong(0L)
6969
private val committedUsage = new AtomicLong(0L)
70+
// Besides the map itself, this lock guards the store directories, their listing entries and
71+
// the committed usage: whether a store is still counted is decided and acted on in one hold.
7072
private val active = new HashMap[(String, Option[String]), Long]()
7173

7274
def initialize(): Unit = {
@@ -139,60 +141,64 @@ private class HistoryServerDiskManager(
139141
* being used so that it's not evicted when running out of designated space.
140142
*/
141143
def openStore(appId: String, attemptId: Option[String]): Option[File] = {
142-
var newSize: Long = 0
143-
val storePath = active.synchronized {
144+
active.synchronized {
144145
val path = appStorePath(appId, attemptId)
145146
if (path.isDirectory()) {
146-
newSize = sizeOf(path)
147+
val newSize = sizeOf(path)
147148
active(appId -> attemptId) = newSize
149+
updateApplicationStoreInfo(appId, attemptId, newSize)
148150
Some(path)
149151
} else {
150152
None
151153
}
152154
}
153-
154-
storePath.foreach { path =>
155-
updateApplicationStoreInfo(appId, attemptId, newSize)
156-
}
157-
158-
storePath
159155
}
160156

161157
/**
162158
* Tell the disk manager that the store for the given application is not being used anymore.
159+
* A tracked store whose directory is already gone is dropped from the listing regardless of
160+
* `delete`.
163161
*
164162
* @param delete Whether to delete the store from disk.
165163
*/
166164
def release(appId: String, attemptId: Option[String], delete: Boolean = false): Unit = {
167165
// Because disk-based stores may modify the structure of the store files even when just reading,
168-
// update the accounting for this application when it's closed.
169-
val oldSizeOpt = active.synchronized {
170-
active.remove(appId -> attemptId)
171-
}
172-
173-
oldSizeOpt.foreach { oldSize =>
174-
updateUsage(-oldSize, committed = true)
175-
}
166+
// update the accounting for this application when it's closed. Do the whole operation under
167+
// the active lock so a concurrent openStore(), commit() or makeRoom() cannot deduct the same
168+
// store size twice.
169+
active.synchronized {
170+
val oldSizeOpt = active.remove(appId -> attemptId)
171+
172+
oldSizeOpt.foreach { oldSize =>
173+
updateUsage(-oldSize, committed = true)
174+
}
176175

177-
// Apply the store operation regardless of whether the app was in the active map, since
178-
// the store directory may still exist on disk (e.g., when the app was never opened after
179-
// a restart).
180-
val path = appStorePath(appId, attemptId)
181-
if (path.isDirectory()) {
182-
if (delete) {
183-
// If the app was not actively tracked, its size was not deducted above; do it now.
184-
if (oldSizeOpt.isEmpty) {
185-
val size = sizeOf(path)
186-
updateUsage(-size, committed = true)
176+
// Apply the store operation regardless of whether the app was in the active map, since
177+
// the store directory may still exist on disk (e.g., when the app was never opened after
178+
// a restart).
179+
val path = appStorePath(appId, attemptId)
180+
if (path.isDirectory()) {
181+
if (delete) {
182+
// If the app was not actively tracked, its size was not deducted above; do it now.
183+
// Measure it from disk rather than trusting the listing: a store directory without a
184+
// listing entry is still counted, since initialize() measures the whole directory.
185+
if (oldSizeOpt.isEmpty) {
186+
val size = sizeOf(path)
187+
updateUsage(-size, committed = true)
188+
}
189+
deleteStore(path)
190+
} else if (oldSizeOpt.isDefined) {
191+
// Re-measure the size since the store may have changed while it was open.
192+
val newSize = sizeOf(path)
193+
val newInfo = listing.read(classOf[ApplicationStoreInfo], path.getAbsolutePath())
194+
.copy(size = newSize)
195+
listing.write(newInfo)
196+
updateUsage(newSize, committed = true)
187197
}
188-
deleteStore(path)
189198
} else if (oldSizeOpt.isDefined) {
190-
// Re-measure the size since the store may have changed while it was open.
191-
val newSize = sizeOf(path)
192-
val newInfo = listing.read(classOf[ApplicationStoreInfo], path.getAbsolutePath())
193-
.copy(size = newSize)
194-
listing.write(newInfo)
195-
updateUsage(newSize, committed = true)
199+
// The store directory is gone (e.g., deleted out of band) and its size was deducted
200+
// above; drop its listing entry too, so makeRoom() does not deduct it again.
201+
deleteStore(path)
196202
}
197203
}
198204
}
@@ -226,6 +232,15 @@ private class HistoryServerDiskManager(
226232
listing.delete(classOf[ApplicationStoreInfo], path.getAbsolutePath())
227233
}
228234

235+
/** Returns the listing entry of the store at `path`, if any. */
236+
private def readStoreInfo(path: String): Option[ApplicationStoreInfo] = {
237+
try {
238+
Some(listing.read(classOf[ApplicationStoreInfo], path))
239+
} catch {
240+
case _: NoSuchElementException => None
241+
}
242+
}
243+
229244
private def makeRoom(size: Long): Unit = {
230245
if (free() < size) {
231246
logDebug(s"Not enough free space, looking at candidates for deletion...")
@@ -246,18 +261,30 @@ private class HistoryServerDiskManager(
246261
}
247262
}
248263

249-
if (evicted.nonEmpty) {
250-
val freed = evicted.map { info =>
251-
logInfo(log"Deleting store for" +
252-
log" ${MDC(APP_ID, info.appId)}/${MDC(APP_ATTEMPT_ID, info.attemptId)}.")
253-
deleteStore(new File(info.path))
254-
updateUsage(-info.size, committed = true)
255-
info.size
256-
}.sum
257-
258-
logInfo(log"Deleted ${MDC(NUM_BYTES_EVICTED, evicted.size)} store(s)" +
259-
log" to free ${MDC(NUM_BYTES_TO_FREE, Utils.bytesToString(freed))}" +
260-
log" (target = ${MDC(NUM_BYTES, Utils.bytesToString(size))}).")
264+
var freedCount = 0
265+
var freedBytes = 0L
266+
evicted.foreach { candidate =>
267+
active.synchronized {
268+
// Re-check under the lock: since the candidate was collected, it may have become
269+
// active, or a concurrent release() or commit() may have deleted it along with its
270+
// listing entry. Deduct the size the listing holds now, which may have changed as well.
271+
if (!active.contains(candidate.appId -> candidate.attemptId)) {
272+
readStoreInfo(candidate.path).foreach { info =>
273+
logInfo(log"Deleting store for" +
274+
log" ${MDC(APP_ID, info.appId)}/${MDC(APP_ATTEMPT_ID, info.attemptId)}.")
275+
deleteStore(new File(info.path))
276+
updateUsage(-info.size, committed = true)
277+
freedCount += 1
278+
freedBytes += info.size
279+
}
280+
}
281+
}
282+
}
283+
284+
if (freedCount > 0) {
285+
logInfo(log"Deleted ${MDC(NUM_APPS, freedCount)} store(s)" +
286+
log" to free ${MDC(NUM_BYTES_EVICTED, Utils.bytesToString(freedBytes))}" +
287+
log" (target = ${MDC(NUM_BYTES_TO_FREE, Utils.bytesToString(size))}).")
261288
} else {
262289
logWarning(log"Unable to free any space to make room for " +
263290
log"${MDC(NUM_BYTES, Utils.bytesToString(size))}.")
@@ -320,29 +347,39 @@ private class HistoryServerDiskManager(
320347
val size = sizeOf(dst)
321348
deleteStore(dst)
322349
updateUsage(-size, committed = true)
350+
} else {
351+
// The store directory is gone (e.g., deleted out of band) but may still be listed and
352+
// counted; drop it before the new store takes over its listing entry.
353+
readStoreInfo(dst.getAbsolutePath()).foreach { info =>
354+
deleteStore(dst)
355+
updateUsage(-info.size, committed = true)
356+
}
323357
}
324358
}
325359

326360
updateUsage(-leased)
327361

328362
val newSize = sizeOf(tmpPath)
329363
makeRoom(newSize)
330-
tmpPath.renameTo(dst)
331364

332-
updateUsage(newSize, committed = true)
365+
// Move the store into place, account for it and mark the app active in one step, so a
366+
// concurrent release() or makeRoom() cannot delete the store before it is tracked.
367+
active.synchronized {
368+
if (!tmpPath.renameTo(dst)) {
369+
throw new IOException(s"Failed to move the store from $tmpPath to $dst")
370+
}
371+
updateUsage(newSize, committed = true)
372+
updateApplicationStoreInfo(appId, attemptId, newSize)
373+
active(appId -> attemptId) = newSize
374+
}
375+
333376
if (committedUsage.get() > maxUsage) {
334377
val current = Utils.bytesToString(committedUsage.get())
335378
val max = Utils.bytesToString(maxUsage)
336379
logWarning(log"Commit of application ${MDC(APP_ID, appId)} / " +
337380
log"${MDC(APP_ATTEMPT_ID, attemptId)} causes maximum disk usage to be " +
338381
log"exceeded (${MDC(NUM_BYTES, current)} > ${MDC(NUM_BYTES_MAX, max)}")
339382
}
340-
341-
updateApplicationStoreInfo(appId, attemptId, newSize)
342-
343-
active.synchronized {
344-
active(appId -> attemptId) = newSize
345-
}
346383
dst
347384
}
348385

0 commit comments

Comments
 (0)