Varnish Cache #3 : Monitoring

Varnish Monitoring Tool 들을 이용해서 Varnish 적용 후 수치들을 확인해 볼 수 있습니다
Cache Hit 비율은 잘 나오는지, Cache Key 가 생각한대로 적용이 되었는지, 메모리는 어느정도 사용하는지 등등입니다

항공권 서비스를 예시로 Varnish 모니터링 도구를 몇개 소개해드릴텐데요
모니터링 실행시 참고하실 사항 몇가지를 먼저 말씀드려 보겠습니다

/home/apps/varnish/bin

앞으로 말씀드릴 varnish 모니터링 실행파일들이 있는 경로 입니다.

-n /home/apps/varnish/var/run

모니터링 파일을 실행시킬때 명령어에 `-n` 옵션으로 varnish working dir 를 지정합니다

varnish working dir 에 대해서는 이전 글에서 가볍게 다뤘었습니다

varnishstat

Varnish 에서 집계하는 각종 수치 를 볼수있는 모니터링 툴입니다
항공권 서비스의 Varnish Cache Hit / Miss 수치, 메모리 사용량을 예시로 확인해보도록 하겠습니다

varnishstat은 다음 명령어로 실행합니다

./varnishstat -n /home/apps/varnish/var/run

Varnish Cache Hit / Miss Counter

실행하면 상단에 MAIN.cache_hit, MAIN.cache_hit_grace, MAIN.cache_miss 같은 수치들이 나옵니다

항목중에 cache_hit / cache_miss 는 말그대로 cache hit / miss 개수를 나타냅니다
cache_hit_grace 는 grace 상태에서 cache hit 을 하게된 수치입니다

grace 세부설명은 이전 글을 참조하시면 됩니다

표 상단에 흰색줄로 표시된 ‘CURRENT / CHANGE / AVERAGE / AVG_XXX’ 는 다음과 같은 의미입니다

• CURRENT : 현재까지 집계된 개수(Counter)
• CHANGE: 초당(per second) 수치 변화 개수
• AVERAGE : 평균값
• AVG_XXX : 지난 최근 모니터링 횟수 XX 사이에 평균

예를들어 AVG_10 이면 CHANGE 가 10번 바뀌었을동안의 평균이라고 생각하시면 됩니다

Varnish Memory Usage

좀더 아래로 내려가보면 `SMA.` 으로 시작하는 항목들이 보입니다
SMA 는 Shared Memory Allocation 의 약자인데요, 지난 글에서 Varnish Shared Memory 에 대해 말씀드린부분과 관련이 있습니다

g_bytes 는 현재 캐싱에 사용되고 있는 메모리 사이즈를 나타냅니다. 2M 정도밖에 안되니는 많이 귀여운 수치네요ㅎㅎ
g_space 는 남아있는 메모리 사이즈입니다. 1021M 정도가 남았네요
이정도면 최초에 Varnish 실행시키면서 `-s malloc,1G` 로 할당했던 메모리 여유공간이 거의 그대로 남아있다는걸 알 수 있습니다

varnishlog

nginx access log 보는것과 비슷하게, Varnish 에서도 유입된 요청 로그들을 확인할수 있습니다

./varnishlog -n /home/apps/varnish/var/run

으로 로그를 확인하실수 있는데요
varnish request / response 에 관련된 거의 모든 항목을 확인해볼수 있다고 생각하시면 됩니다
항목중에 조금 눈여겨 봐야될 부분만 말씀드려보겠습니다

varnishlog 를 실행하면 아래와 같이 로그가 출력됩니다

* << Request >> 5885845 
- Begin req 5885844 rxreq
- Timestamp Start: 1649639945.105580 0.000000 0.000000
- Timestamp Req: 1649639945.105580 0.000000 0.000000
- VCL_use boot
- ReqStart 10.96.24.59 58864 a0
- ReqMethod GET
- ReqURL /?ZZZZZZZZZ
- ReqProtocol HTTP/1.1
(중략…)
- VCL_return hash
- VCL_call HASH
- Hash "XXXXXX"
- Hash "YYYYYY"
- VCL_return lookup
- Hit 5989100 -5.290442 1800.000000 0.000000
- VCL_call HIT
- VCL_return deliver
- Link bereq 5885846 bgfetch
- Timestamp Fetch: 1649639945.105671 0.000091 0.000091
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Server: nginx/1.14.2
(중략..)
- End

로그가 길어서 중간에 생략을 좀 해봤습니다

이중에서 조금 관심있게 볼만한 부분을 발췌해보면 아래와 같은데요

- VCL_return hash
- VCL_call HASH
- Hash "XXXXXX"
- Hash "YYYYYY"
- VCL_return lookup
- Hit 5989100 -5.290442 1800.000000 0.000000
- VCL_call HIT
- VCL_return deliver

Hash 를 보면 cache key가 잘 생성된걸 확인할 수 있습니다

- Hash "XXXXXX"
- Hash "YYYYYY"

VCL_return -> VCL_call 흐름을 보면 VCL flow 가 어떻게 진행되는지도 확인할수가 있네요

VCL flow 는 이전글을 참고해주시면 됩니다

- VCL_call HIT
- VCL_return deliver

varnishhist

varnish 성능이 어떻게 나오는지 시각적으로 보시고 싶다면 varnishhist 를 사용하실수 있습니다
cache hit / miss 수치를 히스토그램(막대그래프) 로 보여주는 모니터링 툴인데요

항공권 Varnish 서버에서 아래 명령으로

./varnishhist -n /home/apps/varnish/var/run

varnishhist 를 실행하면 hit / miss 가 실시간으로 반영되어 히스토그램으로 나타납니다

히스토그램 표기에 대해 설명을 드리면

• ‘|’ 표시는 cache HIT 을 뜻하고
• ‘#’ 표시는 cache MISS 를 뜻합니다

X 축에 있는 시간은 request 를 varnish 가 처리한 내부 처리시간 을 보여주는데요

참고로 여기 나온 시간을 client 에서 호출하고 응답받는 전체 처리시간과 헷갈리시면 안됩니다.

X축 시간 표기의 정의는 ‘request from kernel to Varnish and response from Varnish to kernel’ 입니다

그래프에서 cache hit ( | 표시 ) 를 처리하는 시간은 0.01ms ~ 0.1 ms 사이고

1e-4 = 0.0001 secs or 0.1 ms or 100 µs
1e-5 = 0.00001 secs or 0.01 ms or 10 µs

cache miss ( # 표시 ) 를 처리하는 시간은 1ms ~ 10ms 정도 걸리는걸 확인할 수 있습니다

1e-2 = 0.01 secs or 10 ms
1e-3 = 0.001 secs or 1 ms or 1000 µs (microseconds)

varnish 서버 내부에서 처리되는 속도라는걸 감안하더라도 매우 빠르다는것을 알 수 있습니다
관련해서 좀 더 자세한 설명은 Explaining VarnishHist 를 참고해주시면 되겠습니다

cache MISS 는 왜 생길까?

varnishstat 이나 varnishhist 수치를 보시면, cache MISS 수치가 생각보다 조금 있는데?
라는 의문점이 드실 수 있습니다

여기서 유의하셔서 구분하셔야 될 점이 있는데요
cache key 에 해당하는 데이터가 없을때도 cache MISS 가 되지만
pass 로 처리한 경우도 cache MISS 로 처리됩니다

기억을 잘 돌이켜 보시면 항공권 Varnish서버에서 pass 로 처리한 요청이 하나 있었습니다

sub vcl_recv {
  if (req.url ~ "^/monitor/l7check") {
    return (pass);
  }
  return(hash);
}

3초마다 수행되는 모니터링 요청 /monitor/l7check 는 항상 PASS 가 되어 MISS 수치로 집계되는데요

모니터링 경로로 집계되는 MISS 수치를 구분할수 없는 한계점이 있어도
현재 hit 율이 80% 정도로 나오고 있는점을 보아
캐싱 대상만 고려했을때는 hit 율이 90% 중후반으로 나올것으로 예상됩니다

hit 율 표기는 `varnishstat` 실행시 우측 상단에 노출됩니다

Future work

지금까지 이야기한 모니터링 방식들은 서버에 들어가서 직접 실행해야 볼수있다는 아쉬움이 약간 있는데요
추후에 prometheus varnish exporter 를 연동하게 되면 grafana 로 접속해 수치들을 확인할수도 있을것 같습니다

모쪼록 Varnish 를 적용하시는 분들이 많아지셔서 유용한 기능들과 사용법을 많이 발견하면 좋겠습니다
지금까지 긴글 읽어주셔서 감사합니다~ Varnish 많.관.부!