이번 시간에는 로컬 LLM 에이전트 루프에 OpenTelemetry GenAI 스팬을 달고, Jaeger에 모인 실행 기록만 보고 일부러 느리게 만든 도구 하나를 찾아내며 배워가는 시간입니다.
로컬 LLM 에이전트에게 같은 모델로 같은 과제 45개를 두 번 풀게 했는데, 두 번째 실행은 45개를 끝내는 데 1분 넘게 더 걸렸어요. 과제별 시간만으로는 모델이 느려졌는지, 도구 하나가 느려졌는지, 아니면 그냥 실행마다 생기는 흔들림인지 가릴 수가 없죠.
스팬은 작업 하나가 언제 시작해 얼마나 걸렸는지를 남기는 기록 한 건이라고 보시면 됩니다. 이 스팬을 OpenTelemetry GenAI 시맨틱 컨벤션(생성형 AI 호출을 기록할 때 쓰는 속성 이름 약속)에 맞춰 손으로 달고, Jaeger로 받아 조회 API로 다시 읽어 집계해요.
실습 준비
이 글의 명령은 모두 실습 코드의 agent-otel-tracing/ 디렉터리에서 실행합니다.
compose.yaml: Ollama, Jaeger, Python 클라이언트 컨테이너requirements.txt: 클라이언트 컨테이너가 설치하는 패키지 다섯 개agentlab/: 에이전트 루프·도구·채점·오류 주입 패키지(파일 11개)tasks.jsonl: 과제 45개site.db: 도구가 조회하는 가짜 사이트 DBtrace_run.py: 과제를 돌리고 결과를results/<config>.jsonl에 쌓는 러너tracing.py: OTLP exporter 설정(러너가 불러 씀)otel_hooks.py: 스팬을 여는 hook 객체(러너가 불러 씀)base_summary.py: 결과 파일에서 과제·모델 호출·도구 호출 시간과 도구별 호출 수를 모으는 스크립트make_slow.py: 느린 도구 하나를 골라slow.json에 적는 스크립트find_slow.py: Jaeger 조회 API로 트레이스를 읽어 트리·스팬 이름별 집계를 찍는 스크립트slow_split.py: 느린 도구를 부른 과제와 부르지 않은 과제의 시간 변화를 나누는 스크립트depth_check.py: Jaeger 조회 API에query.searchDepth를 넣었을 때와 뺐을 때 돌아온 트레이스 수를 세는 스크립트
과제에는 깊이가 있습니다. 깊이 1~4는 도구를 1~4번 이어서 불러야 풀리는 템플릿 과제이고, 깊이 0은 템플릿 밖 과제예요. 과제 id는 T<깊이>-<번호> 꼴이라서, 예를 들어 T3-01은 깊이 3의 첫 과제라고 보시면 됩니다.
이 루프에는 hook 자리가 있어요. run_agent(hooks=...)에 객체를 넘기면 루프가 과제 시작과 끝, 모델 호출 앞뒤, 도구 실행 앞뒤에 그 객체의 메서드를 불러 줍니다.
compose.yaml은 ollama/ollama:0.34.4(2,300MB, CPU 2), jaegertracing/jaeger:2.21.0(300MB, CPU 0.25), python:3.12-slim 클라이언트(400MB, CPU 0.25)를 띄워요. 호스트에는 Ollama를 127.0.0.1:7590, Jaeger 조회 화면을 7591, OTLP HTTP 수신을 7592로 열어 두었습니다.
- Ollama의
LLAMA_ARG_CACHE_RAM은 Ollama 안의 llama.cpp 서버가 프롬프트 캐시에 쓰는 메모리 상한(MiB)이에요. 기본 상한이 컨테이너 메모리보다 커서 256으로 낮췄습니다. - Jaeger 2.21.0은 컨테이너 하나로 수신, 저장, 조회 화면을 모두 띄워요. 기본 저장소가 메모리라서 컨테이너를 다시 시작하면 기록이 사라집니다.
- OTLP는 HTTP(4318)만 써요. 클라이언트는 compose 네트워크 안에서
jaeger:4318로 보냅니다.
이제 클라이언트 컨테이너에서 Python 스크립트를 실행하는 셸 함수 lab을 만들고, 컨테이너를 띄운 뒤 모델을 받아 둘게요. 아래 블록은 파일로 만들지 말고 실습 디렉터리에서 연 터미널에 그대로 붙여 넣어 주세요. 이후 명령은 모두 이 터미널에서 실행하고, 터미널을 새로 열면 다시 붙여 넣으시면 됩니다.
lab() { docker compose -p aotel exec -T client python "$@"; }
docker compose -p aotel up -d
docker compose -p aotel exec ollama ollama pull qwen2.5:1.5b
호출 옵션은 temperature 0, seed 42, num_ctx 4096, num_predict 512, num_thread 2, think: false입니다.
스팬을 달기 전에 계측 없이 45개를 한 번 돌려 둘게요. 실행은 러너 trace_run.py가 맡습니다. 과제마다 agentlab의 run_agent를 부른 뒤, 채점 결과와 궤적을 results/<config>.jsonl에 한 줄씩 쌓아요. 요약은 base_summary.py로 냅니다.
lab trace_run.py --config base
lab base_summary.py results/base.jsonl
과제마다 찍히는 한 줄은 빼고 요약만 옮겼어요(발췌).
tasks 45, stop_reason {'answer': 45}
task wall: total 313.2s, median 6.28s, min 3.63s, max 20.18s
model calls 96: total 312.7s, median 2.49s, max 17.88s
tool calls 54: total 169.8ms, median 2.00ms, max 13.90ms
tool call counts: get_like_count 20, search_articles 18, get_course 12, get_article 2, get_author 2
출력을 보면 모델 호출 96번이 312.7초, 도구 호출 54번이 0.17초예요. 도구는 SQLite 조회라서 호출 하나가 2ms 안팎입니다.
느린 도구의 지연은 모델 호출 하나의 중앙값인 2.5초로 정했어요. 지연이 모델 호출보다 훨씬 크면 과제별 시간만 봐도 바로 드러나고, 훨씬 작으면 실행마다의 흔들림에 묻혀 버리거든요. 후보는 45개 과제에서 5번 이상 불린 도구 셋(get_like_count, search_articles, get_course)으로 한정했습니다.
make_slow.py가 계측 없는 실행의 결과 파일을 읽어 그중 하나를 SLOW_SEED=7로 골라 도구 이름과 지연 2.5초를 slow.json에 적어요. 어느 도구인지는 화면에 출력하지 않습니다.
SLOW_SEED=7 lab make_slow.py
candidates: 3 tools, delay 2.5s -> slow.json written
실습 1: hook으로 스팬 달기
hook 객체는 otel_hooks.py의 OtelHooks 클래스예요. 과제가 시작되면 에이전트 스팬 invoke_agent를 엽니다. 그리고 그 스팬을 부모로 하는 컨텍스트를 들고 있다가, 모델 호출 스팬 chat과 도구 호출 스팬 execute_tool을 그 아래에 열어요.
- 실습에만 쓰는 속성은
gen_ai.*와 섞이지 않게lab.*로 이름을 붙였어요. - 도구 결과가 오류면 스팬 상태를 ERROR로 두고
error.type에 도구가 돌려준 오류 종류를 넣어요. - Ollama 응답의
prompt_eval_count(프롬프트 전체 토큰 수)를gen_ai.usage.input_tokens에,prompt_eval_cached_count(그중 캐시를 재사용한 몫)를gen_ai.usage.cache_read.input_tokens에 넣었습니다.
tracing.py의 setup은 환경 변수의 엔드포인트로 보내는 OTLP HTTP exporter를 만들고, BatchSpanProcessor를 붙인 TracerProvider를 전역으로 등록해요. BatchSpanProcessor는 끝난 스팬을 큐에 모았다가 묶어서 보내는 장치예요. 러너 trace_run.py는 --trace를 줬을 때 과제마다 이 hook을 만들어 run_agent에 넘겨요.
find_slow.py는 Jaeger의 조회 API GET /api/v3/traces로 트레이스를 읽어요. 이때 찾을 트레이스 수 상한 query.searchDepth를 항상 1000으로 넣습니다. 생략하면 100이에요.
find_slow.py는 첫 인자로 출력 방식을 받아요. tree는 트레이스마다 루트 스팬 아래 자식 스팬을 시작 시간 순으로 찍습니다. 깊이 3 과제 T3-01 하나를 계측을 켜고 돌린 뒤 트리로 출력해 볼게요.
lab trace_run.py --config lab1 --trace --only T3-01
lab find_slow.py tree --config lab1
1 traces, 6 spans (lab.config=lab1)
trace 5866af8bfa1fed4b486c7cf67782cce6: 6 spans
invoke_agent site-helper INTERNAL + 0.0ms 5734.1ms task=T3-01 stop=answer
chat qwen2.5:1.5b CLIENT + 0.1ms 2002.9ms in=687 cached=656 out=24 finish=['stop']
execute_tool get_course INTERNAL + 2003.2ms 3.2ms tool=get_course ERROR not_found
chat qwen2.5:1.5b CLIENT + 2006.5ms 2477.0ms in=756 cached=702 out=23 finish=['stop']
execute_tool get_course INTERNAL + 4483.7ms 2.2ms tool=get_course ERROR not_found
chat qwen2.5:1.5b CLIENT + 4486.0ms 1247.7ms in=825 cached=778 out=5 finish=['stop']
출력을 보면 invoke_agent 아래에 chat과 execute_tool이 실행 순서대로 번갈아 나와요. 이 과제는 모델 호출 3번, 도구 호출 2번이라 스팬 수는 3 + 2 + 1 = 6이고, 출력도 6개입니다.
첫 모델 호출은 프롬프트 687토큰 가운데 656토큰을 캐시에서 읽었으니, 새로 처리한 것은 31토큰입니다.
실습 2: 계측을 켜고 세 번 돌리기
45개 과제를 계측을 켜고 3번 돌려요. find_slow.py names는 스팬 이름마다 걸린 시간을 모아 개수, 합계, 중앙값, 최댓값을 내고, 합계가 큰 순으로 찍어요. 첫 회는 이렇습니다.
lab trace_run.py --config lab2 --trace --runs 3
lab find_slow.py names --config lab2 --run 1
45 traces, 195 spans (lab.config=lab2)
span name count total median max share
invoke_agent 45 298.18s 5828.0ms 18766.4ms 100.0%
chat qwen2.5:1.5b 96 298.02s 2457.2ms 16822.3ms 99.9%
execute_tool search_articles 18 0.05s 2.5ms 4.5ms 0.0%
execute_tool get_course 12 0.04s 2.0ms 7.1ms 0.0%
execute_tool get_like_count 20 0.03s 1.7ms 3.0ms 0.0%
execute_tool get_author 2 0.01s 3.5ms 4.9ms 0.0%
execute_tool get_article 2 0.00s 1.7ms 2.0ms 0.0%
share는 invoke_agent 합계에 대한 비율이에요. CPU로 모델을 돌리는 이 환경에서는 모델 호출이 전체의 99.9%를 차지했고, 같은 명령을 --run 2, --run 3으로 바꿔 본 2회와 3회도 99.9%였습니다.
세 번 모두 45개 과제의 도구 호출 순서가 계측 없는 실행과 같았어요. 세 번의 차이는 다음 범위였어요.
- 과제 시간 합계: 298.2초, 322.0초, 319.5초. 계측 없는 실행은 313.2초였어요.
chat스팬 중앙값: 2,457.2ms, 2,697.6ms, 2,719.6ms- 도구 스팬 중앙값: 도구마다 1.7~4.0ms
같은 궤적인데도 합계가 24초까지 흔들린다는 점을 기억해 두세요.
트레이스가 135개(45개 × 3회)가 된 지금, query.searchDepth를 빼고 한 번, 1000으로 넣고 한 번 조회해 돌아온 트레이스 수를 세 볼게요.
lab depth_check.py
no searchDepth: 100 traces
{'query.searchDepth': 1000}: 135 traces
이 값을 빼면 오류 없이 100개만 돌아와요. 집계 스크립트가 이렇게 잘린 결과를 받으면 숫자가 조용히 틀립니다.
실습 3: 느린 도구 찾기
이제 slow.json을 켜고 45개를 한 번 더 돌린 뒤 스팬 이름별로 모아 볼게요.
lab trace_run.py --config lab3 --trace --slow slow.json
lab find_slow.py names --config lab3
45 traces, 195 spans (lab.config=lab3)
span name count total median max share
invoke_agent 45 364.99s 7185.1ms 20932.0ms 100.0%
chat qwen2.5:1.5b 96 319.69s 2731.8ms 18516.0ms 87.6%
execute_tool get_like_count 20 45.11s 2505.3ms 2516.1ms 12.4%
execute_tool search_articles 18 0.09s 3.7ms 11.6ms 0.0%
execute_tool get_course 12 0.03s 3.1ms 4.8ms 0.0%
execute_tool get_author 2 0.01s 5.6ms 8.0ms 0.0%
execute_tool get_article 2 0.00s 2.5ms 2.7ms 0.0%
execute_tool get_like_count의 중앙값이 2,505.3ms예요. 다른 도구 스팬은 2.5~5.6ms이고, 실습 2의 같은 스팬 중앙값은 세 번 모두 1.7~2.4ms였습니다.
그래서 출력만 보고 get_like_count를 지목한 뒤에 slow.json을 열어 봤어요.
cat slow.json
{"tool": "get_like_count", "seconds": 2.5}
지목한 도구가 맞았어요. 느린 도구는 두 가지 숫자로 봐야 해요.
호출당 시간(중앙값)으로 보면 get_like_count가 모델 호출과 비슷한 크기로 튀어 올라서 바로 보여요. 반면 전체에서 차지하는 시간(합계)으로 보면 45.11초, 12.4%로 chat의 319.69초보다 훨씬 작습니다. 하루에 몇 번 안 불리는 도구가 느려졌다면 합계로는 거의 보이지 않았을 거예요.
과제별 시간 목록만으로는 왜 도구를 특정할 수 없는지도 숫자로 확인해 볼게요. slow_split.py는 실습 3의 과제마다 slow.json의 도구를 몇 번 불렀는지 세어 두 무리로 나누고, 실습 2 첫 회 대비 과제 시간 변화를 모으는 스크립트예요.
lab slow_split.py
called get_like_count: 19 tasks, calls 20, time change vs lab2 run1 median +2.90s (min +1.93, max +4.97), sum +58.2s
not called get_like_count: 26 tasks, calls 0, time change vs lab2 run1 median +0.49s (min -1.98, max +2.16), sum +8.6s
출력을 보면 부르지 않은 과제도 최대 2.16초까지 느려졌고, 부른 과제 중 가장 적게 늘어난 것은 1.93초였어요. 두 무리가 겹치는 거죠.
chat 합계도 실습 2 첫 회 298.02초에서 319.69초로 21.7초 늘었습니다. 늘어난 66.8초 중 45.1초가 도구, 21.7초가 모델 호출의 흔들림이었던 셈이에요. 그런데 과제별 시간 목록에는 이 둘이 섞여서 한 숫자로만 남습니다.
정리
범위: Ollama 0.34.4의 qwen2.5:1.5b(CPU 추론), OpenTelemetry Python SDK 1.45.0, Jaeger 2.21.0, 과제 45개.
- 느린 도구를 넣은 실행에서 늘어난 66.8초 중 45.1초는 도구, 21.7초는 모델 호출의 흔들림이었고, 그 도구를 부르지 않은 과제도 최대 2.16초 느려졌어요. 과제별 전체 시간이 아니라 스팬 이름별로 모아 보세요.
- 2.5초 늦춘
get_like_count는 중앙값 2,505.3ms로 다른 도구 스팬 2.5~5.6ms보다 수백 배 컸지만, 합계로는 45.11초, 12.4%였어요. 느린 도구는 합계 순으로만 고르지 말고 호출당 중앙값을 함께 보세요. - Jaeger 조회 API는
query.searchDepth를 빼면 트레이스 135개 중 100개만 오류 없이 돌려줬어요. 조회할 때는query.searchDepth를 항상 넣어 주세요.