feat: add processing time queries per pipeline step and per document

Added 3 new queries/panels:
- Processing Time by Pipeline Step (avg, p50, p90, max per step)
- Total Document Processing Time (end-to-end workflow summary)
- Per-Document Processing Time Breakdown (individual step timing)

Queries parse elapsed time from traces logged by queue_handler_base
and claim_processor workflow.

Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>

Author: Prachig-Microsoft

infra/dashboards/token-usage-queries.kql

@@ -293,7 +293,66 @@ customEvents
     by process_id, Step = agent
 | order by process_id, TotalTokens desc
 
-// 18. Daily processing volume with token costs
+// 18. Processing time per pipeline step
+traces
+| where timestamp > ago(7d)
+| where message has "Pipeline stage completed"
+| parse message with * "process_id=" process_id ", document=" document ", stage=" stage ", elapsed=" elapsed
+| where isnotempty(stage)
+| extend elapsed_parts = split(elapsed, ":")
+| extend hours = toint(elapsed_parts[0])
+| extend mins = toint(elapsed_parts[1])
+| extend sec_parts = split(tostring(elapsed_parts[2]), ".")
+| extend secs = toint(sec_parts[0])
+| extend ms = toint(sec_parts[1])
+| extend elapsed_seconds = hours * 3600.0 + mins * 60.0 + secs + ms / 100.0
+| summarize
+    AvgSeconds = round(avg(elapsed_seconds), 2),
+    P50Seconds = round(percentile(elapsed_seconds, 50), 2),
+    P90Seconds = round(percentile(elapsed_seconds, 90), 2),
+    MaxSeconds = round(max(elapsed_seconds), 2),
+    Invocations = count()
+    by Step = stage
+| order by AvgSeconds desc
+
+// 19. Total document processing time (end-to-end workflow)
+traces
+| where timestamp > ago(7d)
+| where message has "Workflow elapsed time"
+| parse message with * "Workflow elapsed time: " elapsed " (start=" * ", end=" *
+| where isnotempty(elapsed)
+| extend elapsed_parts = split(elapsed, ":")
+| extend hours = toint(elapsed_parts[0])
+| extend mins = toint(elapsed_parts[1])
+| extend sec_parts = split(tostring(elapsed_parts[2]), ".")
+| extend secs = toint(sec_parts[0])
+| extend ms = toint(sec_parts[1])
+| extend elapsed_seconds = hours * 3600.0 + mins * 60.0 + secs + ms / 100.0
+| summarize
+    DocumentsProcessed = count(),
+    AvgSeconds = round(avg(elapsed_seconds), 2),
+    P50Seconds = round(percentile(elapsed_seconds, 50), 2),
+    P90Seconds = round(percentile(elapsed_seconds, 90), 2),
+    P95Seconds = round(percentile(elapsed_seconds, 95), 2),
+    MaxSeconds = round(max(elapsed_seconds), 2)
+
+// 20. Per-document processing time breakdown by step
+traces
+| where timestamp > ago(7d)
+| where message has "Pipeline stage completed"
+| parse message with * "process_id=" process_id ", document=" document ", stage=" stage ", elapsed=" elapsed
+| where isnotempty(stage)
+| extend elapsed_parts = split(elapsed, ":")
+| extend hours = toint(elapsed_parts[0])
+| extend mins = toint(elapsed_parts[1])
+| extend sec_parts = split(tostring(elapsed_parts[2]), ".")
+| extend secs = toint(sec_parts[0])
+| extend ms = toint(sec_parts[1])
+| extend elapsed_seconds = round(hours * 3600.0 + mins * 60.0 + secs + ms / 100.0, 2)
+| project timestamp, process_id, document, Step=stage, ElapsedSeconds=elapsed_seconds
+| order by process_id, timestamp asc
+
+// 21. Daily processing volume with token costs
 customEvents
 | where name == 'LLM_Agent_Token_Usage'
 | where timestamp > ago(30d)

infra/dashboards/token-usage-workbook.json

@@ -217,6 +217,55 @@
       },
       "name": "tokens-by-filetype"
     },
+    {
+      "type": 1,
+      "content": {
+        "json": "---\n## Processing Time"
+      },
+      "name": "section-processing-time"
+    },
+    {
+      "type": 3,
+      "content": {
+        "version": "KqlItem/1.0",
+        "query": "traces\r\n| where timestamp > ago(7d)\r\n| where message has \"Pipeline stage completed\"\r\n| parse message with * \"process_id=\" process_id \", document=\" document \", stage=\" stage \", elapsed=\" elapsed\r\n| where isnotempty(stage)\r\n| extend elapsed_parts = split(elapsed, \":\")\r\n| extend hours = toint(elapsed_parts[0])\r\n| extend mins = toint(elapsed_parts[1])\r\n| extend sec_parts = split(tostring(elapsed_parts[2]), \".\")\r\n| extend secs = toint(sec_parts[0])\r\n| extend ms = toint(sec_parts[1])\r\n| extend elapsed_seconds = hours * 3600.0 + mins * 60.0 + secs + ms / 100.0\r\n| summarize\r\n    AvgSeconds = round(avg(elapsed_seconds), 2),\r\n    P50Seconds = round(percentile(elapsed_seconds, 50), 2),\r\n    P90Seconds = round(percentile(elapsed_seconds, 90), 2),\r\n    MaxSeconds = round(max(elapsed_seconds), 2),\r\n    Invocations = count()\r\n    by Step = stage\r\n| order by AvgSeconds desc",
+        "size": 0,
+        "title": "Processing Time by Pipeline Step",
+        "timeContextFromParameter": "TimeRange",
+        "queryType": 0,
+        "resourceType": "microsoft.insights/components",
+        "visualization": "table"
+      },
+      "name": "processing-time-by-step"
+    },
+    {
+      "type": 3,
+      "content": {
+        "version": "KqlItem/1.0",
+        "query": "traces\r\n| where timestamp > ago(7d)\r\n| where message has \"Workflow elapsed time\"\r\n| parse message with * \"Workflow elapsed time: \" elapsed \" (start=\" * \", end=\" *\r\n| where isnotempty(elapsed)\r\n| extend elapsed_parts = split(elapsed, \":\")\r\n| extend hours = toint(elapsed_parts[0])\r\n| extend mins = toint(elapsed_parts[1])\r\n| extend sec_parts = split(tostring(elapsed_parts[2]), \".\")\r\n| extend secs = toint(sec_parts[0])\r\n| extend ms = toint(sec_parts[1])\r\n| extend elapsed_seconds = hours * 3600.0 + mins * 60.0 + secs + ms / 100.0\r\n| summarize\r\n    DocumentsProcessed = count(),\r\n    AvgSeconds = round(avg(elapsed_seconds), 2),\r\n    P50Seconds = round(percentile(elapsed_seconds, 50), 2),\r\n    P90Seconds = round(percentile(elapsed_seconds, 90), 2),\r\n    P95Seconds = round(percentile(elapsed_seconds, 95), 2),\r\n    MaxSeconds = round(max(elapsed_seconds), 2)",
+        "size": 3,
+        "title": "Total Document Processing Time (End-to-End)",
+        "timeContextFromParameter": "TimeRange",
+        "queryType": 0,
+        "resourceType": "microsoft.insights/components",
+        "visualization": "table"
+      },
+      "name": "total-processing-time"
+    },
+    {
+      "type": 3,
+      "content": {
+        "version": "KqlItem/1.0",
+        "query": "traces\r\n| where timestamp > ago(7d)\r\n| where message has \"Pipeline stage completed\"\r\n| parse message with * \"process_id=\" process_id \", document=\" document \", stage=\" stage \", elapsed=\" elapsed\r\n| where isnotempty(stage)\r\n| extend elapsed_parts = split(elapsed, \":\")\r\n| extend hours = toint(elapsed_parts[0])\r\n| extend mins = toint(elapsed_parts[1])\r\n| extend sec_parts = split(tostring(elapsed_parts[2]), \".\")\r\n| extend secs = toint(sec_parts[0])\r\n| extend ms = toint(sec_parts[1])\r\n| extend elapsed_seconds = round(hours * 3600.0 + mins * 60.0 + secs + ms / 100.0, 2)\r\n| project timestamp, process_id, document, Step=stage, ElapsedSeconds=elapsed_seconds\r\n| order by process_id, timestamp asc",
+        "size": 0,
+        "title": "Per-Document Processing Time Breakdown",
+        "timeContextFromParameter": "TimeRange",
+        "queryType": 0,
+        "resourceType": "microsoft.insights/components",
+        "visualization": "table"
+      },
+      "name": "per-document-time-breakdown"
+    },
     {
       "type": 1,
       "content": {