Skip to content

Commit c871949

Browse files
committed
refactor workflow to avoid cpu contention and related issues
1 parent 39e1d7f commit c871949

14 files changed

Lines changed: 1089 additions & 653 deletions

File tree

docs/ARCHITECTURE.md

Lines changed: 14 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -87,10 +87,9 @@ claim-with-lease persistence layer:
8787
alongside.
8888
- **Pluggable metrics**`Metrics` protocol with a default
8989
`LoggingMetrics` no-op. Counters: `claim_attempts`,
90-
`claim_success`, `claim_idle`, `claim_error`, `claim_lost_race`,
91-
`step_completed`, `step_error`, `step_failed`, `step_released`,
92-
`worker_reaped`, `lease_lost`, `resource_lock_swept`. Histograms:
93-
`claim_duration`, `step_duration`.
90+
`claim_success`, `claim_idle`, `claim_error`, `step_completed`,
91+
`step_error`, `step_failed`, `step_released`, `worker_reaped`,
92+
`lease_lost`. Histograms: `claim_duration`, `step_duration`.
9493

9594
Two workers can coexist in one process because nothing in the runner
9695
is module-global anymore; legacy module-level `start_worker` /
@@ -168,17 +167,21 @@ graph LR
168167
### Workflow Execution Flow
169168

170169
1. **Worker Startup** - `Worker.start()` spawns per-type consumer
171-
loops plus heartbeat / reaper / lock-sweeper background tasks
170+
loops plus heartbeat / reaper background tasks
172171
2. **Step Claim** - Consumer calls `claim_next_step` with a fresh
173172
lease token; atomic `UPDATE-FROM-SELECT-FOR-UPDATE-SKIP-LOCKED`
174-
marks the row RUNNING. Steps whose `resource_key` is currently
175-
locked are skipped at the SQL layer
176-
3. **Resource Lock Acquire** - If the step declared a
177-
`resource_key`, the worker acquires the matching `ResourceLock`
178-
row (TTL-refreshed on heartbeat)
173+
marks the row RUNNING and (if the step has a `resource_key`)
174+
inserts the matching `ResourceLock` row in the same transaction.
175+
Steps whose `resource_key` is currently held are skipped at the
176+
SQL layer.
177+
3. **In-Process Serialization** - The worker takes a per-key
178+
`asyncio.Lock` before invoking the user step handler, so two
179+
consumer coroutines targeting the same `resource_key` serialize
180+
without DB I/O and without TTL semantics
179181
4. **Status Transition** - PENDING → RUNNING → COMPLETED / ERROR /
180182
FAILED; terminal writes are gated on the lease so a stale
181-
worker cannot double-finalize
183+
worker cannot double-finalize. The `ResourceLock` row is
184+
cleared in the same transaction as the terminal write.
182185
5. **Step Execution** - Calls registered handler method
183186
6. **Artifact Storage** - Saves intermediate results
184187
7. **Retry Logic** - `error_step` increments retry; elevates to

docs/DATABASE.md

Lines changed: 15 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -599,23 +599,26 @@ here.
599599
- `holder_kind` (ResourceLockKind) - `worker`, `cli`, `web`, or `lifecycle`
600600
- `step_id` (int, nullable) - Set when held by a worker on behalf of a step
601601
- `acquired_at` (datetime) - When the lock was acquired
602-
- `expires_at` (datetime, indexed) - TTL boundary; refreshed by holder heartbeats
602+
- `expires_at` (datetime, indexed) - TTL boundary for non-worker
603+
holders. Worker holders use a far-future sentinel so the row is
604+
cleared by step-status transitions, not by a TTL sweep.
603605
- `holder_meta` (dict[str, str]) - JSON metadata
604606

605607
**Lifecycle:**
606608

607-
- Acquired via `operations.acquire_resource_lock(...)` — opportunistically
608-
sweeps expired rows before attempting insert under the unique primary key
609-
- TTL-refreshed via `refresh_resource_lock(...)` (workers refresh on
610-
heartbeat at half the TTL)
611-
- Released via `release_resource_lock(...)` (idempotent) or
609+
- Worker holders: inserted atomically by `claim_next_step` in the
610+
same transaction as the `RunStep` status update. Dropped by
611+
`complete_step` / `error_step` / `release_step` in the same
612+
transaction as the step terminal write, or by
613+
`reap_dead_workers` keyed on lease token.
614+
- CLI / web / lifecycle holders: acquired via
615+
`operations.acquire_resource_lock(...)` with a real TTL, which
616+
opportunistically sweeps expired rows before attempting insert
617+
under the unique primary key. Released via
618+
`release_resource_lock(...)` (idempotent) or
612619
`force_release_resource_lock(...)` (audit-logged, used by
613-
`si-diag vacuum --force`)
614-
- Dropped automatically by `complete_step` / `error_step` /
615-
`release_step` in the same transaction as the step terminal
616-
write
617-
- Expired rows are swept by `sweep_expired_resource_locks()` on a
618-
60-second loop in each worker
620+
`si-diag vacuum --force`). Expired rows are also swept on demand
621+
by `sweep_expired_resource_locks()`.
619622

620623
**Example:**
621624

docs/WORKFLOWS.md

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -589,15 +589,13 @@ production:
589589
| `claim_success` | A step was claimed |
590590
| `claim_idle` | No work was available |
591591
| `claim_error` | The claim query raised |
592-
| `claim_lost_race` | Step's `resource_key` was held between claim and acquire|
593592
| `step_completed` | Successful terminal write |
594593
| `step_error` | Retryable failure |
595594
| `step_failed` | Retries exhausted |
596595
| `step_released` | Cooperative release on shutdown |
597596
| `step_reset_by_reaper` | A dead worker's step was reset to PENDING |
598597
| `worker_reaped` | A peer worker was reaped |
599598
| `lease_lost` | Terminal write found a non-matching lease (labelled `phase`) |
600-
| `resource_lock_swept` | Expired `ResourceLock` rows were swept |
601599

602600
| Histogram | Description |
603601
|-------------------|--------------------------------------|
@@ -711,8 +709,11 @@ points at a holder that no longer exists.
711709

712710
**Solution:**
713711
1. Inspect the lock: `SELECT * FROM resourcelock WHERE resource_key='rag:/path/to/db'`
714-
2. The background `sweep_expired_resource_locks` loop clears
715-
expired holders every 60s; if the row is genuinely stuck,
712+
2. Worker-held lock rows are cleared when the step completes,
713+
errors, is released, or the holder is reaped via
714+
`WorkerCheckin`. CLI/web/lifecycle holders use a real TTL and
715+
are cleared opportunistically by `acquire_resource_lock` or by
716+
`sweep_expired_resource_locks`. If the row is genuinely stuck,
716717
break it from the CLI:
717718

718719
```bash

src/soliplex/ingester/lib/config.py

Lines changed: 0 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -84,7 +84,6 @@ class Settings(BaseSettings):
8484
embeddings_store_dir: str = "embeddings"
8585
stop_phrases: list[str] = []
8686

87-
ingest_queue_concurrency: int = 20
8887
ingest_worker_concurrency: int = 10
8988
docling_concurrency: int = 3
9089
input_s3: S3Settings = S3Settings()

src/soliplex/ingester/lib/docling.py

Lines changed: 103 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,4 @@
1+
import asyncio
12
import http.cookiejar as cj
23
import json
34
import logging
@@ -27,6 +28,20 @@
2728
"max_tokens": 200,
2829
}
2930

31+
# Process-wide async semaphore that bounds the number of concurrent
32+
# in-flight requests to the docling-serve backend. Initialized lazily
33+
# so it binds to the running event loop on first use; tests that
34+
# spin up fresh loops should reset this back to None between cases
35+
# (see ``tests/conftest.py``).
36+
_docling_sem: asyncio.Semaphore | None = None
37+
38+
39+
def get_docling_sem() -> asyncio.Semaphore:
40+
global _docling_sem
41+
if _docling_sem is None:
42+
_docling_sem = asyncio.Semaphore(get_settings().docling_concurrency)
43+
return _docling_sem
44+
3045

3146
def do_repl(data):
3247
if isinstance(data, dict):
@@ -39,7 +54,14 @@ def do_repl(data):
3954

4055

4156
def is_html(file_bytes: bytes) -> bool:
42-
return (file_bytes.startswith(b"<!DOCTYPE html>") or b"<html" in file_bytes[:100]) and b"<body" in file_bytes
57+
"""Detect HTML from the leading bytes only.
58+
59+
The ``<html`` check stays at the first 100 bytes (matches the
60+
original behavior). The ``<body`` check is bounded to the first
61+
8 KB so non-HTML payloads (e.g. multi-MB PDFs) do not trigger a
62+
full-buffer ``bytes.find``.
63+
"""
64+
return (file_bytes.startswith(b"<!DOCTYPE html>") or b"<html" in file_bytes[:100]) and b"<body" in file_bytes[:8192]
4365

4466

4567
@retry(stop=stop_after_attempt(4), wait=wait_exponential_jitter(), reraise=True)
@@ -52,17 +74,53 @@ async def docling_convert(
5274
) -> dict:
5375
"""Convert a document via the docling-serve HTTP backend.
5476
55-
Concurrency for ``parse`` steps is now bounded at the worker
56-
level by the ``parse`` consumer pool count
57-
(``Worker(consumers={"parse": N, ...})``); the library does no
58-
rate-limiting of its own. To preserve the previous default,
59-
operators should set ``consumers["parse"]`` equal to
60-
``settings.docling_concurrency``.
77+
Process-wide concurrency to docling-serve is bounded by
78+
``settings.docling_concurrency`` via the module-global
79+
``_docling_sem``. The semaphore wraps only the HTTP / websocket
80+
/ result-GET round trip — large-document post-processing
81+
(recursive image-placeholder substitution and whole-tree
82+
re-serialization) runs outside the slot and on a worker thread,
83+
so CPU work cannot starve docling-serve capacity.
84+
85+
The semaphore is acquired *inside* the tenacity retry so a
86+
failing attempt releases its slot while it waits to retry.
87+
88+
Note: the gate is per-process. If multiple worker processes
89+
share one docling-serve, the server sees
90+
``N_workers * docling_concurrency`` aggregate parallelism; in
91+
that topology, rate-limit at the proxy or in docling-serve's
92+
own queue instead.
93+
"""
94+
async with get_docling_sem():
95+
res, parameters = await _docling_request(
96+
file_bytes,
97+
mime_type,
98+
source_uri,
99+
config_dict,
100+
output_formats,
101+
)
102+
return await asyncio.to_thread(_process_result, res, parameters, source_uri, output_formats)
103+
104+
105+
async def _docling_request(
106+
file_bytes: bytes,
107+
mime_type: str,
108+
source_uri: str,
109+
config_dict: dict[str, str | int | bool],
110+
output_formats: list[str],
111+
) -> tuple[dict, dict]:
112+
"""POST + websocket wait + result GET against docling-serve.
113+
114+
Returns ``(res, parameters)``. ``res`` is the parsed result
115+
document; ``parameters`` is the request body as sent (the
116+
caller needs ``image_export_mode`` from it to decide on
117+
placeholder replacement). Raises ``ValueError`` on protocol
118+
errors, which the outer ``@retry`` retries.
61119
"""
62120
env = get_settings()
63121
local_jar = cj.CookieJar()
64122
async_url = f"{env.docling_server_url}/convert/file/async"
65-
parameters = {
123+
parameters: dict = {
66124
"from_formats": [
67125
"docx",
68126
"pptx",
@@ -102,7 +160,6 @@ async def docling_convert(
102160
parameters["do_picture_description"] = False
103161

104162
file_name = source_uri.split("/")[-1]
105-
106163
if mime_type and "markdown" in mime_type and not file_name.endswith(".md"):
107164
file_name = file_name + ".md"
108165
# docling requires some special handling for html
@@ -112,9 +169,7 @@ async def docling_convert(
112169

113170
f = BytesIO(file_bytes)
114171
try:
115-
files = {
116-
"files": (file_name, f, mime_type),
117-
}
172+
files = {"files": (file_name, f, mime_type)}
118173
logger.debug(f"using {parameters} on {file_name}")
119174
async with httpx.AsyncClient(timeout=env.docling_http_timeout, cookies=local_jar) as _async_client:
120175
response = await _async_client.post(async_url, files=files, data=parameters)
@@ -143,28 +198,48 @@ async def docling_convert(
143198
logger.error(f"no errors in response: {payload}")
144199
result_url = f"{env.docling_server_url}/result/{task_id}"
145200
response = await _async_client.get(result_url)
146-
res = response.json()
201+
# The result body carries the full Docling document, which
202+
# can be many MB. ``response.json()`` runs stdlib
203+
# ``json.loads`` on the calling thread — offload so the
204+
# event loop stays responsive while it parses.
205+
res = await asyncio.to_thread(response.json)
206+
logger.info(f"{task_id} result={res.get('status')} processing time={res.get('processing_time')}")
147207
finally:
148208
f.close()
209+
return res, parameters
210+
211+
212+
def _process_result(
213+
res: dict,
214+
parameters: dict,
215+
source_uri: str,
216+
output_formats: list[str],
217+
) -> dict:
218+
"""Validate the docling-serve result and re-serialize each
219+
requested output format.
220+
221+
Pure Python. ``do_repl`` walks the entire JSON tree and
222+
``json.dumps`` re-serializes it — seconds of work on a large
223+
document. Designed to run on a worker thread (see the
224+
``asyncio.to_thread`` call in :func:`docling_convert`).
225+
"""
149226
if "status" not in res:
150227
raise ValueError(f"no status in response: {res}")
151-
logger.info(f"{task_id} result={res['status']} processing time={res['processing_time']}")
152-
153-
if res["status"] == "success":
154-
parsed = {}
155-
for output_format in output_formats:
156-
output_content = res["document"][f"{output_format}_content"]
157-
if output_format == "json":
158-
if "image_export_mode" in parameters and parameters["image_export_mode"] == "placeholder":
159-
logger.info(f" doing placeholder replacement for {source_uri}")
160-
output_content = do_repl(output_content)
161-
parsed[output_format] = json.dumps(output_content).encode("utf-8")
162-
else:
163-
parsed[output_format] = str(output_content).encode("utf-8")
164-
return parsed
165-
else:
228+
if res["status"] != "success":
166229
raise ValueError(str(res["errors"]))
167230

231+
parsed: dict[str, bytes] = {}
232+
for output_format in output_formats:
233+
output_content = res["document"][f"{output_format}_content"]
234+
if output_format == "json":
235+
if parameters.get("image_export_mode") == "placeholder":
236+
logger.info(f" doing placeholder replacement for {source_uri}")
237+
output_content = do_repl(output_content)
238+
parsed[output_format] = json.dumps(output_content).encode("utf-8")
239+
else:
240+
parsed[output_format] = str(output_content).encode("utf-8")
241+
return parsed
242+
168243

169244
def get_docling_schema_version() -> str:
170245
import docling_core.types.doc.document as dd

src/soliplex/ingester/lib/rag.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -360,7 +360,7 @@ async def save_to_rag(
360360
logger.info(f"Found existing document {found[0].id}", extra=_log_con)
361361
doc_id = found[0].id
362362
await client.delete_document(doc_id)
363-
logger.debug(f"deleted existing document {found[0].id}", extra=_log_con)
363+
logger.info(f"deleted existing document {found[0].id}", extra=_log_con)
364364

365365
new_doc = await client.import_document(
366366
chunks=chunks,

src/soliplex/ingester/lib/wf/operations.py

Lines changed: 10 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1770,13 +1770,21 @@ def _utc_now() -> datetime.datetime:
17701770
RunStatus.ERROR,
17711771
)
17721772

1773+
# Sentinel expires_at for WORKER-held ``ResourceLock`` rows. Worker
1774+
# locks have no functional TTL — they're cleared by complete_step,
1775+
# error_step, release_step, or reap_dead_workers — but the row must
1776+
# still satisfy ``subq_locked``'s ``expires_at > now`` predicate and
1777+
# stay clear of the opportunistic ``WHERE expires_at < now`` sweep.
1778+
# CLI/web/lifecycle holders going through ``acquire_resource_lock``
1779+
# continue to use real TTLs.
1780+
_WORKER_LOCK_EXPIRES = datetime.datetime(9999, 12, 31)
1781+
17731782

17741783
async def claim_next_step(
17751784
worker_id: str,
17761785
lease_token: str,
17771786
allowed_types: list[WorkflowStepType] | None = None,
17781787
batch_id: int | None = None,
1779-
resource_lock_ttl: int = 300,
17801788
holder_meta: dict[str, str] | None = None,
17811789
) -> RunStep | None:
17821790
"""Atomically claim the next eligible step for *worker_id*.
@@ -1821,7 +1829,6 @@ async def claim_next_step(
18211829
atomic resource-lock insert lost a race.
18221830
"""
18231831
now = _utc_now()
1824-
expires = now + datetime.timedelta(seconds=resource_lock_ttl)
18251832
async with get_session() as session:
18261833
# Subquery 1: minimum step number per eligible workflow run.
18271834
subq_min_step = (
@@ -1927,7 +1934,7 @@ async def claim_next_step(
19271934
holder_kind=ResourceLockKind.WORKER,
19281935
step_id=step.id,
19291936
acquired_at=now,
1930-
expires_at=expires,
1937+
expires_at=_WORKER_LOCK_EXPIRES,
19311938
holder_meta=holder_meta or {"worker_id": worker_id},
19321939
),
19331940
)

0 commit comments

Comments
 (0)