September 18, 2026

AI-Assisted Log Analysis

Typical applications have a few GB of data and their log files are also a few GB. So, any computer can easily process this amount data. You can process it on the spot with Unix tools and pipes. But writing those pipes takes some time, especially if you do not analyze logs daily.

In my opinion, AI clankers are a game changer for looking through log files. I ask the AI questions, and the AI clanker answers them using Unix pipes, Unix tools, and small Python scripts.

왜 못 챁아요?

For example, a few days ago I investigated slow responses:

1. An unknown log file format

I didn’t know the log file format, so I simply asked:

Shortened/summarized transcript:
> What can these logs tell me. What information is in it?

# AI는 생각하고 도구 호출
# Python 스크립트 3개 사용했어요.

These are AWS Application Load Balancer (ALB) access logs for the load balancer.
They record one line per HTTP(S) request handled by the ALB.
What each entry can tell you

They include:

    Timestamp in UTC
    Client source IP and port
    Backend target that served the request, e.g. 10.1.2.151:8090
    Request method, URL/path, protocol, such as GET /healthcheck HTTP/1.1
    Host header and User-Agent
    ALB and backend HTTP status codes
    Timing:
        time spent receiving the request
        backend/target processing time
        time spent returning the response
    Request/response byte sizes
    TLS version and cipher
    Target group, selected target, routing action (forward or redirect)
    AWS trace ID, useful for correlating with application tracing

# 그리고 나중에

   Response outcomes
   ALB status   Count    Interpretation
   -----------  -------  -------------------------------------------
   200          2,693    Successful
   301          212      Permanent redirect, likely HTTP -> HTTPS
   302          188      Temporary redirect
   404          532      Resource not found
   400          129      Invalid/malformed request; many rejected at the ALB
   405          10       Unsupported method
   401          9        Authentication required/failed
   406          3        Not acceptable
   460          6        Client disconnected before the target responded

# ...

Performance

For requests that reached a target:

    Median backend processing time: 4 ms
    95th percentile: 685 ms
    99th percentile: 1.864 s
    Slowest request: 24.181 s

# ....

2. Asking about the problematic time

I knew when the problem occurred, so I asked what was going on during that time.

Shortened/summarized transcript:
> Around the time Sep 11, 2026 08:20:00 UTC, what requests got answered. What was the response time, status code etc.
> Overview of a window of 10 minutes before and after the provided timestamp.

# AI는 스크립트 더 사용했어요.

# ...

Notable events

    08:10:49.040 — GET /v1/some-endpoint, routed to 10.1.2.252:8090, resulted in ALB 460.
    This means the client disconnected before a response was completed; consequently, no target status or target duration was recorded.

    08:11:18.717 — GET /v1/some-endpoint, served by 10.1.2.151:8090:
        ALB status / target status: 200 / 200
        Target processing: 24.181 s
        This is the clear latency outlier in the window.

    08:29:36.410 — GET /v1/some-endpoint, served by 10.1.2.151:8090:
        Status: 200 / 200
        Target processing: 7.347 s
        A second, less severe slow request.

# ...

3. Analyzing another log file together

So, I now knew there were slow HTTP requests. I also had log files from another system. So I analyzed them together:

Shortened/summarized transcript:
> In the @other-system-log-2026-09-14.csv, is there any slow request that reponds to the slow times in the access logs.
Longer than 5 secons?

# AI는 생각하고 도구 호출

I matched on the endpoint and completion timestamp. The CSV message timestamp includes Z (UTC), and for the successful requests below it is within 1–8 ms of the ALB log timestamp. All are:

GET /v1/some-endpoint

   Completion time (UTC)      ALB target (s)   App logged (s)   App request ID
   ------------------------  ---------------  ---------------  ------------------------------------
   2026-09-11 01:51:43.109            7.331            6.484  f19460c8-2377-43e3-95dd-1cac292f7aab
   2026-09-11 07:33:18.573           23.563           23.637  adfbebe6-6641-48e9-9f70-4a93b0d135a6
   2026-09-11 07:33:36.271           22.168           21.892  f391b41f-c774-4f7a-b2cf-95af7c847c77
   2026-09-11 07:33:55.070           10.284           10.338  e6d8499b-acb4-473d-9a25-2db694cd1059
   2026-09-11 07:50:43.006            5.391            5.377  a349c7d7-60ec-45ae-be3c-a1c5e025bf81
   2026-09-11 08:11:18.717           24.181           24.209  67bd04c9-6ebc-45d3-9c8c-b173a6a0962d
   2026-09-11 08:29:36.411            7.347            7.408  dbf81ef9-d6c9-40a7-b7ce-ed7b023dd0e8
   2026-09-11 10:39:52.976           15.441           15.396  defaa4da-2f36-40fe-b354-3782caef6f5d
   2026-09-11 11:35:42.570            5.299            5.184  53333c14-c6e5-4c1e-870b-5e733b0f0346

4. Timeline

Then I wanted to know the timeline of a slow request.

Shortened/summarized transcript:
> Create a timeline for the request f391b41f-c774-4f7a-b2cf-95af7c847c77

# The AI thinks and makes tool calls

   UTC time                Elapsed        Event
   ----------------------  -------------  ------------------------------------------------------------
   07:33:14.099            +0 ms          ALB created the request.
   07:33:14.103            +4 ms          Approximate start of ALB target processing.
   07:33:14.378            +279 ms        Application began handling GET /v1/some-endpoint on worker nio-8090-exec-6.
   07:33:14.585            +486 ms        Began fetching the requested data, data-ids etc.
   07:33:15.466            +1.367 s       Initial file fetch completed: 890 ms, 793 bytes. Rendering began.
   07:33:15.578            +1.479 s       Began fetching extra data 1.
   07:33:15.965            +1.866 s       extra data 2 fetched: 388 ms, 3,880 bytes.
   07:33:15.980            +1.881 s       Began fetching extra data 2.
   07:33:16.265            +2.166 s       extra data 2 fetched: 285 ms, 250 bytes.
   07:33:16.274            +2.175 s       Began fetching extra data 3.
   07:33:16.465            +2.366 s       extra 3 fetched: 191 ms, 893 bytes.
   07:33:16.471            +2.372 s       Began fetching extra data 4.
   07:33:16.865            +2.766 s       extra data 4 fetched: 394 ms, 2,775 bytes.
   07:33:16.872            +2.773 s       Began fetching extra data 5.
   07:33:17.165            +3.066 s       extra data 5 fetched: 294 ms, 279 bytes.
   ...
   07:33:17.567-17.571     +3.47 s        More stuff happened.
   07:33:17.571-29.081     11.510 s gap   No request-specific application log events. This is likely uninstrumented processing/rendering time.
   07:33:29.081-29.087     +14.98 s       Some stuff got skipped
   07:33:29.087-36.086     6.999 s gap    No request-specific application log events before rendering finishes.
   07:33:36.086            +21.987 s      Application logged "Processing complete."
   07:33:36.269            +22.170 s      Application completed the request: 21,891.538 ms.
   07:33:36.271            +22.172 s      ALB recorded 200 / 200; target processing was 22.168 s.

# AI abbreviated ...

5. Java Flight Recorder data

Maybe there was a JVM problem, like GC pause? So I also added the Java Flight Recorder file. And now the AI uses Java: It writes small Java snippets to analyze the Flight recording and incoperates it into the analysis.

Shortened/summarized transcript:
> There is now a @debug.jfr for the Java Flight recorder. Are there any events from when are large gaps in the logs?

# The AI thinks and makes tool calls

JFR findings during Sep 14 slow-request windows

   Log window           Slow request durations          JFR execution samples   Some-Feature-related samples
   -------------------  ------------------------------  ----------------------  ------------------------
   08:19:38-08:19:45    6.103 s                         60                      60 / 60
   08:44:03-08:44:43    7.097-33.556 s                  160                     156 / 160
   09:00:51-09:01:09    5.211 s and 17.797 s            6                       6 / 6

The sampled stacks are dominated by Some-Feature rendering and PNG generation, including:

    net.a.library.*
    net.a.library.png.SomeOperation.*
    net.a.library.png.Png.write
    com.sun.imageio.plugins.png.PNGImageWriter.encodePass
    java.awt.image.BufferedImage.*
    References to other code

For example, in the 08:19 slow request window, the JFR repeatedly sampled:

BufferedImage.getRGB
SomeOperation.packMeIfPossible
Png.write
GraphicStuff.writeToStream
ImageBuilder.writeImageInternal

# ...

GC activity during the 08:44 slow-request burst

There was also substantial G1 old-generation GC activity while four requests took 7–34 seconds:

   Start time (UTC)   GC event                                    Wall-clock duration   Longest stop-the-world pause
   -----------------  ------------------------------------------  --------------------  -----------------------------
   08:44:12.901       G1 Old, triggered by humongous allocation   3.104 s               491 ms
   08:44:19.384       G1 Old                                      2.816 s               293 ms
   08:44:26.290       G1 Old                                      3.498 s               535 ms
   09:00:51.875       G1 Old, triggered by humongous allocation   2.210 s               464 ms

6. I analyzed further, but you get the gist

I analyzed further. For example, I found the top 10 slowest requests and looked for similar operations among the slow requests.

Thanks to AI, you can think about the questions instead of thinking about Unix pipes.

I highly can recommend using a Clanker to investigate log files.

Tags: Development