Pular para o conteúdo principal

Job statistics

Per-stage elapsed-time statistics on the dashboard — what is collected, how each number is calculated, and how to read them when processing feels slow.

At a glance

QuestionAnswer
Where do the numbers live?The operational store — one row per completed job. They survive restarts, and in a cluster every instance shows the same deployment-wide figures.
How do I turn it on or off?Statistics:Enabled (default true). When false, nothing is recorded and the dashboard panel disappears.
What is measured?Four stages per job — queue wait, signing, verification, output creation — plus a total (their sum).
What is not measured?The two human waits: the Lacuna Signer AwaitingSigner wait and the AwaitingApproval wait. Both are deliberately excluded — see below.
Where do I see it?The Dashboard home page, "Processing performance" panel. Refreshes on the normal dashboard poll (Dashboard:PollIntervalSeconds).
How do I clear it?Clear Jobs moves a deployment-wide reset marker. Nothing is deleted — see Resetting the panel.
Want durable history outside the product?Scrape /api/metricsbulksigner_signing_duration_seconds is the external record (see REST API).
Changed in 2.0.0

The numbers used to live in process memory and reset on every restart. They are now rows in the operational store, which is what makes the panel survive a restart and describe a whole cluster rather than whichever instance answered. One card was retired in the move — see "Max throughput/sec" is gone.

What is collected

For every job the pipeline times four stages, measured with a monotonic clock at exact code boundaries:

StageStarts atEnds at
Queue waitJob entered the queue (QueuedAt)Worker picks the job up (transition to Processing)
SigningLocal: just before the signature call. Remote: just before document creation (dispatch) and just before the signed download (poll)Immediately after each of those calls returns
VerificationJust before the signature is verifiedImmediately after it returns (skipped jobs contribute no sample)
Output creationEncrypt (if enabled) + write to processing/After promote-to-output/ and delete-original

Total = queue wait + signing + verification + output. This is the active machine time the job cost end to end. It is not the created-to-completed wall clock for a remote job, because that would include the human-signing wait.

When the job reaches Completed, those four durations are written to the store as one row, alongside the completion timestamp and whether the job was signed Local or Remote (Lacuna Signer). Every figure on the panel is an aggregate over those rows.

A stage that did not happen is stored as null, never as zero: a job whose profile sets Verify = false has no verification sample, so it neither drags that stage's average down nor inflates its count. The total still sums the stages that did happen.

Where the numbers live, and what that buys

One row per completed job, in the same database as the jobs themselves, cascaded away with its job. Three consequences worth knowing:

  • They survive a restart. There is no "since boot" window any more. The caption says how many jobs have completed and since when, where "since when" is the last reset if there has been one and otherwise the oldest completion still on record.
  • Every instance shows the same numbers. Under cluster mode the dashboard you reach is whichever instance the load balancer picked, and the panel describes the whole deployment rather than that instance's share of it.
  • They grow with completed jobs and nothing else. A handful of numeric columns per job, bounded by a job count the store already carries.

A job in flight is still measured in process memory and only becomes a row when it completes. So a host killed mid-job loses that job's partial timings: the job records nothing rather than something wrong, and every job that finished before the restart is unaffected.

What each dashboard metric means

The "Processing performance" panel shows:

MetricMeaning
Avg job timeMean of the per-job total (active time).
Avg signingMean signing-stage time. For remote jobs this is dispatch + download, not the wait between them.
Avg verificationMean verification-stage time. Jobs that skip verification (Verify = false) are not counted, so this average reflects only jobs that actually verified.
Throughput (last min)Completions in the trailing 60 seconds, expressed per minute — a responsive "right now" rate.
Total processing time — Min / Avg / MaxThe extreme and mean per-job totals, in hh:mm:ss.fff form. Min and Max are single-job observations, useful for spotting outliers.
Average by stage — Queue wait / OutputMean intake-backlog time and mean output-materialisation time (encryption + promote).
By method — Local (n) / Remote (n)Mean total for locally-signed vs Lacuna-Signer jobs, with the sample count in parentheses.
LifetimeCompleted jobs ÷ the window the rows cover, expressed per minute.

The caption shows how many jobs have completed and the start of that window.

Durations render in two forms: rounded prose on the stat cards (2 min 14 sec, 3.4 sec, 421 ms) and fixed hh:mm:ss.fff in the min/avg/max row (00:00:03.421). A stage with no samples yet shows an em dash (). Durations are stored to the millisecond, which is exactly the finest resolution either rendering shows.

"Max throughput/sec" is gone

There used to be a card showing the busiest single wall-clock second observed. It measured one process's lifetime, so under a cluster it would have described one instance's luck, and there is no honest way to reconstruct a deployment-wide equivalent from completion timestamps. It was retired rather than approximated. "Throughput (last min)" answers the question it was mostly being read for, and bulksigner_signing_duration_seconds on /api/metrics is unchanged and still the external record.

How elapsed time is calculated

Timing uses a monotonic clock source, unaffected by wall-clock adjustments (NTP steps, DST), so a clock change mid-job cannot produce a negative or wildly wrong span. Each measured span wraps exactly one operation; negative spans from clock edge cases are floored at zero before they are stored.

A job's partial timings are held in an in-flight entry keyed by job id while it processes. The remote path spans two workers — one records the dispatch span, the other records the download, verify and output spans onto the same entry once the document comes back, on the same instance, because a job is owned by one instance from pickup to terminal status. On successful completion the entry becomes a row; on any failure, cancel or timeout it is discarded, so a job that never finishes neither leaks memory nor skews the averages.

Why the human waits are excluded

A Lacuna Signer document can sit in AwaitingSigner for hours or days while a person signs it (Signer:TimeoutHours defaults to a full week). If that wait were folded into "average signing time", a single slow human would dominate every number and the panel would stop telling you anything about system performance. So the wait between dispatch and download is never timed. To see how long documents are parked awaiting signature, use the AwaitingSigner count on the dashboard, the per-job AwaitingSignerSince timestamp, or the bulksigner_jobs_awaiting_signer metric — see Lacuna Signer integration.

The AwaitingApproval wait is excluded for the same reason, and more bluntly: parking discards the job's in-flight entry outright, so a parked job contributes nothing at all. To see how long jobs have been parked, use the "Awaiting approval" card and the per-row wait duration on /jobs, the per-job AwaitingApprovalSince timestamp, or the bulksigner_jobs_awaiting_approval metric — see Approvals.

A released job is measured from the release, not from when the file arrived. Once the quorum is met the job re-enters the queue and is picked up fresh, opening a second timing entry — and that entry's queue wait is anchored on QueuedAt, which the release re-stamps. Without that anchor the second pickup would measure from CreatedAt and quietly re-import the whole approval wait the exclusion above exists to keep out. So a job that waited two days for a quorum and then signed in 400 ms contributes a 400 ms job, which is the honest reading of what the pipeline did.

Resetting the panel

Running Clear Jobs records a deployment-wide reset marker: from then on the aggregates count only jobs that completed after it. It takes effect on every instance at once, because the marker is a row rather than a variable in one process.

Three things follow, and the second one is the point:

  • Nothing is deleted to clear the panel. The rows a reset hides are still stored and still queryable. What does remove a row is the job going — a deleted job takes its timings with it, through the foreign key.
  • A job the clear left alone keeps its measurement. Clear Jobs deletes only jobs the pipeline has finished with; an unfinished one survives, and when it later completes its row lands after the marker and counts.
  • The reset rolls back with the clear. The marker moves inside the clear's transaction, so a clear that fails leaves the panel exactly as it was.

The Prometheus histogram is a monotonic counter and is not affected by any of this.

Using the statistics to diagnose slow processing

Read the stage split to localise a slowdown:

SymptomLikely causeWhere to look next
Queue wait high, everything else normalBacklog — files arrive faster than the worker drains themRaise Pipeline:MaxConcurrency (mind the PKCS#11 / Windows-store caveat in Configuration); check the Queued count
Signing high on Local jobsSlow certificate source — HSM/PKCS#11 round-trips, a contended token at MaxConcurrency > 1, or Key Vault latencyCertificates; consider keeping token-backed profiles at MaxConcurrency = 1
Signing high on Remote jobsSlow Lacuna Signer API (create/download), not the human waitbulksigner_signer_api_errors_total, network to the Signer endpoint; Lacuna Signer integration
Verification highLarge artifacts or slow revocation/chain checks during verifyProfile Verify settings; artifact sizes
Output highEncryption cost or slow output/ storage (network share, slow disk)Encryption; the output/ volume
MaxAvgA few outliers (large files, a transient stall)Sort recent jobs by size; check logs around the spike
Throughput (last min)LifetimeA current stall or pausePipeline pause state; the live "In progress" / "Slots busy" card

Because the rows persist, the panel is now a trend signal as well as a live one — the window it covers is however long you have been keeping completed jobs. For analysis outside the product, scrape the Prometheus endpoint into Grafana; the bulksigner_signing_duration_seconds histogram is the durable counterpart, and it is unaffected by resets.

In a cluster, read the panel and /api/metrics differently

The panel is deployment-wide because it aggregates rows. /api/metrics is per process and a scrape reaches an arbitrary instance, so a per-instance gauge read as a fleet total under-reports — see High availability.

Configuration

KeyTypeDefaultEnv overrideNotes
Statistics:EnabledbooltrueStatistics__EnabledMaster switch. false makes the collector a no-op, writes no row, and hides the dashboard panel. Turning it off does not delete rows already recorded — turning it back on shows them again.

Next: Telemetry — optional Application Insights integration. Previous: Dashboard.