Finding Out Why An Azure OpenAI Chatbot Is Slow With Log Analytics

Also see Azure AI Foundry And OpenAI Deployments For A Chatbot App

A client said their chatbot “fails all the time”. I had a Foundry resource, a Container App and a pile of debug traces, but no way to say how often it really failed or where the time went. This post is how I got from guessing to measuring: turn on Foundry request logs, write the app’s own traces to the same Log Analytics workspace, join the two on a correlation id, and wrap the lot in a Claude Code skill so I can re-run it after every change.

The problem

Two things were true at once:

  • Answers were slow. Typically 30 to 40 seconds, sometimes over 90.
  • One assistant failed far more often than the others with “temporarily unavailable”.

The Foundry metrics looked healthy (about 95% of gpt-5 calls succeeded, quota was nowhere near the limit) and the app’s debug traces were a small sample from people testing. The traces did show the cause of the failures: the chat service allows at most four model calls per answer, forces one search per call, and that assistant’s prompt searches one brand at a time. Questions covering several brands ran out of calls and threw. That is our code, not an Azure error.

The slowness was harder. Nearly all the time was inside the model calls, but I couldn’t see Azure’s side of those calls, token usage, or the real failure rate. I wanted a baseline I could trust before changing any code, so I could tell if each change actually helped.

1. Send Foundry logs to Log Analytics

Foundry keeps no request logs unless you add a diagnostic setting. This goes next to the account in foundry.tf:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
resource "azurerm_monitor_diagnostic_setting" "foundry" {
  name                       = "foundry-to-log-analytics"
  target_resource_id         = azurerm_cognitive_account.main.id
  log_analytics_workspace_id = azurerm_log_analytics_workspace.main.id

  enabled_log {
    category = "RequestResponse"
  }

  enabled_log {
    category = "AzureOpenAIRequestUsage"
  }

  enabled_log {
    category = "Audit"
  }
}

I put it in foundry.tf because it belongs to the account and goes away with it. The cost is log ingestion only.

Logs only flow from the moment it is applied, and the first rows took about 30 minutes to show up. Before that the table doesn’t even exist, so an empty result in the first half hour isn’t a failure.

Docs: Monitor Azure OpenAI • azurerm_monitor_diagnostic_setting

2. Apply just that one resource

terraform plan also wanted to change the Container App, because my GitHub Actions pipeline sets the image, env vars and secrets on it and Terraform saw that as drift. Applying everything would have wiped that config until the next deploy.

Terraform can’t apply “only the changes in foundry.tf“, because it treats every file in the folder as one configuration. What it understands is the resource address, so use -target:

1
2
3
terraform plan  -target=azurerm_monitor_diagnostic_setting.foundry -out=targeted.tfplan
terraform apply targeted.tfplan
rm targeted.tfplan

The saved plan means apply does exactly what you reviewed. Plan output prints env var values in plain text, so keep it out of tickets and chat (and delete the plan file).

Docs: Resource targeting

3. What the Foundry logs give you, and what they don’t

Once traffic arrives the logs land in AzureDiagnostics:

Category What it holds
RequestResponse One row per call: operation, status code, DurationMs, CorrelationId, caller IP
AzureOpenAIRequestUsage Prompt, cached and generated tokens, time to first token, whether it streamed (in properties_s)
Audit Management and key-access events, empty until something happens

They do not contain prompts or responses. I looked for a setting to turn that on and there isn’t one for this diagnostic setting. That’s actually fine for a baseline: I wanted timings, status codes and tokens for every call, not content.

The usage rows arrive a minute or two after the request rows, so don’t query the last couple of minutes and conclude something is missing.

4. Write the app’s traces to the same workspace

The app already wrote a debug trace per chat request to blob storage as JSON. Useful, but I’d have to download files to analyse them, and I couldn’t query them next to the Foundry rows.

Container Apps ships stdout to ContainerAppConsoleLogs_CL, one row per line, so the cheapest way into Log Analytics is writing the trace to the console as single-line JSON. I added a setting so it can be switched off:

1
2
3
4
"ChatDebugTracing": {
  "Enabled": true,
  "LogToConsole": true
}

A few details that mattered:

  • One line per object. A multi-line message becomes several rows. A compact JSON string avoids that.
  • Long text is split. Prompts get big, so step detail over 6000 characters is written as numbered parts (part and parts) that you reassemble by trace id.
  • Two line types. chat_trace is one per request (status, total time, error). chat_step is one per step (name, start, duration, detail).
  • Content is in there. Prompts, responses and the user’s email land in the workspace, readable by anyone with access to it, so the setting is the off switch.

The existing blob traces stayed as they were.

Docs: Container Apps log monitoring

5. Record an id that joins to Foundry

Every app line has the same traceId, so one chat is easy to pull. Linking it to Foundry is the clever part. Foundry’s CorrelationId is generated by Azure, so I can’t set it myself. But Azure returns request ids in the response headers, and the SDK exposes the raw response. For each model call I record the token usage and those headers on the step:

1
2
3
4
5
6
var headers = result.GetRawResponse().Headers;
foreach (var header in new[] { "x-request-id", "apim-request-id", "x-ms-request-id", "x-ms-client-request-id" })
{
    if (headers.TryGetValue(header, out var value) && !string.IsNullOrWhiteSpace(value))
        properties[header] = value;
}

I didn’t know which header, if any, would match, so I deployed it and made a test chat. In my test it was apim-request-id: it equals CorrelationId in both RequestResponse and AzureOpenAIRequestUsage. The other headers didn’t match anything. The token counts the app recorded also equalled Foundry’s, which is a good sanity check that the join is right.

6. Join them in KQL

Pull a model-call step from the app lines, then join to the Foundry rows:

1
2
3
4
5
6
7
8
9
10
11
12
13
let steps = ContainerAppConsoleLogs_CL
| where Log_s startswith '{"evt":"chat_step"' and Log_s contains 'complete-chat.attempt'
| extend j = parse_json(Log_s)
| where toint(j.part) == 1
| project traceId = tostring(j.traceId), appMs = tolong(j.durationMs),
          reqId = tostring(j.properties["apim-request-id"]);
steps
| join kind=leftouter (
    AzureDiagnostics
    | where Category == "RequestResponse" and OperationName =~ "chatcompletions_create"
    | project CorrelationId, azureMs = DurationMs, ResultSignature
  ) on $left.reqId == $right.CorrelationId
| extend overheadMs = appMs - azureMs

part == 1 matters because a long step is split across rows and the properties are only on the first part.

appMs - azureMs is the time spent outside the model (network, client). In my test it was 100 to 400 ms on calls that took 15 to 23 seconds, so the delay is inside Azure, not our code or the network. The same test showed that about 87% of the output tokens were reasoning tokens and the calls weren’t streamed, so nothing reached the user until the whole answer was done. That’s one chat, so it’s a lead, not a conclusion, but it tells me where to look first (lower reasoning effort and streaming).

A failed call (408, 429) usually has no app step, because the app throws before recording it. Those show up as Foundry rows with no match, which is exactly the thing the Foundry logs add.

Docs: join operator • parse_json

7. Make it repeatable with skills

Typing that KQL after every change gets old, and I wanted a before and an after I could compare. Two things helped.

First, my azdebug skills from my skills marketplace. /azdebug:loganalytics finds the workspace and runs read-only KQL against Container Apps logs and the Foundry tables, and /azdebug:foundry reports status codes, failure timing and quota for model deployments. Both only use the Azure CLI and never print message bodies.

1
2
claude plugin marketplace add carlpaton/skills
claude plugin install azdebug@carlpaton

Second, a project skill in the app repo, chat-performance-report, that uses the same helper to do the whole job. I run it and say “give me the logs for the last 24 hours”. It asks which environment, pulls the app traces and the Foundry rows, joins them on apim-request-id and writes a report plus a metrics.json:

1
2
reports/2026-11-12_07-23-50Z_<env>.md
reports/2026-11-12_07-23-50Z_<env>.metrics.json

The report has the headline numbers:

  • success, canceled and error rates
  • request time p50, p90 and p95
  • model calls per request, and how often the four-call cap was hit
  • app-measured vs Azure-measured call time
  • time to first token
  • reasoning share of output tokens

It also shows where the time goes (model, search, everything else) and a Data availability table. That table matters: an environment without the Foundry setting still produces a report, but it says which source is missing instead of guessing. After a change I run it again and compare the two metrics files:

1
python3 -I chat_report.py compare <before>.metrics.json <after>.metrics.json

It prints each measure with better, same (within 5%) or worse. Because the files are named by time and environment, I can run it days apart. One caveat I kept in the skill: with a handful of requests none of the rates mean anything, so compare like with like (same environment, same assistant) and wait for real traffic before trusting a result.

What I’d do again

Turn the logging on before touching the code. I now have numbers for every call, from both sides, and a way to join them, so the next change gets a real before and after instead of an argument. The changes themselves (parallel tool calls, a final answer when the cap is hit, skipping search for greetings, streaming and lower reasoning effort) come next, one at a time.