fix: rewrite processing time queries to use customEvents timestamps

The trace-based queries weren't working because Python Azure Monitor SDK
stores log templates and args separately. New approach:
- Step Completion Time: uses LLM_Agent_Token_Usage event timestamps to
  compute time from doc start to each step's completion
- OpenAI API Call Durations: uses dependencies table for HTTP call times
- Per-Document Step Timeline: shows when each step completed per document
- Total Processing Time: first-to-last step duration per document

All queries now use customEvents/dependencies tables which reliably
capture data from both ContentProcessor and ContentProcessorWorkflow.

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

Author: Prachig-Microsoft

infra/dashboards/token-usage-queries.kql

@@ -293,65 +293,76 @@ customEvents
     by process_id, Step = agent
 | order by process_id, TotalTokens desc
 
-// 18. Processing time per pipeline step
-traces
+// 18. Step completion time (seconds from document start to step completion)
+customEvents
+| where name == 'LLM_Agent_Token_Usage'
 | 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
+| extend agent = tostring(customDimensions['agent_name'])
+| extend process_id = tostring(customDimensions['process_id'])
+| join kind=inner (
+    customEvents
+    | where name == 'LLM_Agent_Token_Usage'
+    | where timestamp > ago(7d)
+    | extend process_id = tostring(customDimensions['process_id'])
+    | summarize DocStartTime = min(timestamp) by process_id
+) on process_id
+| extend StepDurationSeconds = round(datetime_diff('millisecond', timestamp, DocStartTime) / 1000.0, 2)
 | 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),
+    AvgCompletionTime = round(avg(StepDurationSeconds), 2),
+    P50CompletionTime = round(percentile(StepDurationSeconds, 50), 2),
+    P90CompletionTime = round(percentile(StepDurationSeconds, 90), 2),
+    MaxCompletionTime = round(max(StepDurationSeconds), 2),
     Invocations = count()
-    by Step = stage
-| order by AvgSeconds desc
+    by Step = agent
+| order by AvgCompletionTime desc
 
-// 19. Total document processing time (end-to-end workflow)
-traces
+// 19. OpenAI API call durations from dependencies table
+dependencies
 | 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
+| where target has "openai" or name has "chat" or type == "HTTP" or name has "openai"
+| where success == true
+| extend durationSeconds = round(duration / 1000.0, 2)
 | 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)
+    TotalCalls = count(),
+    AvgSeconds = round(avg(durationSeconds), 2),
+    P50Seconds = round(percentile(durationSeconds, 50), 2),
+    P90Seconds = round(percentile(durationSeconds, 90), 2),
+    MaxSeconds = round(max(durationSeconds), 2)
+    by OperationName = name
+| order by TotalCalls desc
+| take 10
 
-// 20. Per-document processing time breakdown by step
-traces
+// 20. Per-document step timeline
+customEvents
+| where name == 'LLM_Agent_Token_Usage'
 | 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
+| extend agent = tostring(customDimensions['agent_name'])
+| extend process_id = tostring(customDimensions['process_id'])
+| join kind=inner (
+    customEvents
+    | where name == 'LLM_Agent_Token_Usage'
+    | where timestamp > ago(7d)
+    | extend process_id = tostring(customDimensions['process_id'])
+    | summarize DocStartTime = min(timestamp) by process_id
+) on process_id
+| extend StepCompletedAt = round(datetime_diff('millisecond', timestamp, DocStartTime) / 1000.0, 2)
+| project timestamp, process_id, Step=agent, StepCompletedAtSeconds=StepCompletedAt
 | order by process_id, timestamp asc
 
+// 21. Total document processing time (first to last step)
+customEvents
+| where name == 'LLM_Agent_Token_Usage'
+| where timestamp > ago(7d)
+| extend process_id = tostring(customDimensions['process_id'])
+| summarize StartTime = min(timestamp), EndTime = max(timestamp) by process_id
+| extend TotalSeconds = round(datetime_diff('millisecond', EndTime, StartTime) / 1000.0, 2)
+| summarize
+    DocumentsProcessed = count(),
+    AvgSeconds = round(avg(TotalSeconds), 2),
+    P50Seconds = round(percentile(TotalSeconds, 50), 2),
+    P90Seconds = round(percentile(TotalSeconds, 90), 2),
+    MaxSeconds = round(max(TotalSeconds), 2)
+
 // 21. Daily processing volume with token costs
 customEvents
 | where name == 'LLM_Agent_Token_Usage'

infra/dashboards/token-usage-workbook.json

@@ -228,9 +228,9 @@
       "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",
+        "query": "customEvents\r\n| where name == 'LLM_Agent_Token_Usage'\r\n| where timestamp > ago(7d)\r\n| extend agent = tostring(customDimensions['agent_name'])\r\n| extend process_id = tostring(customDimensions['process_id'])\r\n| join kind=inner (\r\n    customEvents\r\n    | where name == 'LLM_Agent_Token_Usage'\r\n    | where timestamp > ago(7d)\r\n    | extend process_id = tostring(customDimensions['process_id'])\r\n    | summarize DocStartTime = min(timestamp) by process_id\r\n) on process_id\r\n| extend StepDurationSeconds = round(datetime_diff('millisecond', timestamp, DocStartTime) / 1000.0, 2)\r\n| summarize\r\n    AvgCompletionTime = round(avg(StepDurationSeconds), 2),\r\n    P50CompletionTime = round(percentile(StepDurationSeconds, 50), 2),\r\n    P90CompletionTime = round(percentile(StepDurationSeconds, 90), 2),\r\n    MaxCompletionTime = round(max(StepDurationSeconds), 2),\r\n    Invocations = count()\r\n    by Step = agent\r\n| order by AvgCompletionTime desc",
         "size": 0,
-        "title": "Processing Time by Pipeline Step",
+        "title": "Step Completion Time (seconds from doc start)",
         "timeContextFromParameter": "TimeRange",
         "queryType": 0,
         "resourceType": "microsoft.insights/components",
@@ -242,30 +242,44 @@
       "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)",
+        "query": "dependencies\r\n| where timestamp > ago(7d)\r\n| where target has \"openai\" or name has \"chat\" or type == \"HTTP\" or name has \"openai\"\r\n| where success == true\r\n| extend durationSeconds = round(duration / 1000.0, 2)\r\n| summarize\r\n    TotalCalls = count(),\r\n    AvgSeconds = round(avg(durationSeconds), 2),\r\n    P50Seconds = round(percentile(durationSeconds, 50), 2),\r\n    P90Seconds = round(percentile(durationSeconds, 90), 2),\r\n    MaxSeconds = round(max(durationSeconds), 2)\r\n    by OperationName = name\r\n| order by TotalCalls desc\r\n| take 10",
+        "size": 0,
+        "title": "OpenAI API Call Durations",
         "timeContextFromParameter": "TimeRange",
         "queryType": 0,
         "resourceType": "microsoft.insights/components",
         "visualization": "table"
       },
-      "name": "total-processing-time"
+      "name": "openai-call-durations"
     },
     {
       "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",
+        "query": "customEvents\r\n| where name == 'LLM_Agent_Token_Usage'\r\n| where timestamp > ago(7d)\r\n| extend agent = tostring(customDimensions['agent_name'])\r\n| extend process_id = tostring(customDimensions['process_id'])\r\n| join kind=inner (\r\n    customEvents\r\n    | where name == 'LLM_Agent_Token_Usage'\r\n    | where timestamp > ago(7d)\r\n    | extend process_id = tostring(customDimensions['process_id'])\r\n    | summarize DocStartTime = min(timestamp) by process_id\r\n) on process_id\r\n| extend StepCompletedAt = round(datetime_diff('millisecond', timestamp, DocStartTime) / 1000.0, 2)\r\n| project timestamp, process_id, Step=agent, StepCompletedAtSeconds=StepCompletedAt\r\n| order by process_id, timestamp asc",
         "size": 0,
-        "title": "Per-Document Processing Time Breakdown",
+        "title": "Per-Document Step Timeline",
         "timeContextFromParameter": "TimeRange",
         "queryType": 0,
         "resourceType": "microsoft.insights/components",
         "visualization": "table"
       },
       "name": "per-document-time-breakdown"
     },
+    {
+      "type": 3,
+      "content": {
+        "version": "KqlItem/1.0",
+        "query": "customEvents\r\n| where name == 'LLM_Agent_Token_Usage'\r\n| where timestamp > ago(7d)\r\n| extend process_id = tostring(customDimensions['process_id'])\r\n| summarize StartTime = min(timestamp), EndTime = max(timestamp) by process_id\r\n| extend TotalSeconds = round(datetime_diff('millisecond', EndTime, StartTime) / 1000.0, 2)\r\n| summarize\r\n    DocumentsProcessed = count(),\r\n    AvgSeconds = round(avg(TotalSeconds), 2),\r\n    P50Seconds = round(percentile(TotalSeconds, 50), 2),\r\n    P90Seconds = round(percentile(TotalSeconds, 90), 2),\r\n    MaxSeconds = round(max(TotalSeconds), 2)",
+        "size": 3,
+        "title": "Total Document Processing Time (First to Last Step)",
+        "timeContextFromParameter": "TimeRange",
+        "queryType": 0,
+        "resourceType": "microsoft.insights/components",
+        "visualization": "table"
+      },
+      "name": "total-processing-time"
+    },
     {
       "type": 1,
       "content": {