뉴렐릭은 애플리케이션 성능 모니터링(APM)을 폭넓게 사용해 사내 서비스를 관찰하고 조정하고 있습니다. APM은 관련 메트릭과 트레이스를 수집해 서비스 문제를 식별하고 진단하는 데 유용합니다. 그러나 모든 항목들을 미리 측정하는 것은 사실상 불가능한 일입니다. 인시던트 발생 후에, 또는 세부적인 조사를 위해 계측을 추가하는 것이 우수한 관행이지만, 이미 보유한 데이터를 사용해 지금 당장 문제를 해결하고 싶다면 어떻게 해야 할까요?
로그가 이러한 문제에 도움이 될 수 있습니다!
로그는 어떤 장점이 있을까요?
파일에 기록된 비정형 텍스트는 가장 오래된 형태의 텔레메트리라고 할 수 있습니다. 현대 컴퓨팅이 시작된 이래로 프로그램들은 텍스트를 생성해왔습니다. 이렇게 곳곳에 존재하는 로그는 정보의 보고입니다. 다른 정보는 부족할지 몰라도 무슨 일이 일어났는지 알려주는 로그가 어디에선가 생성되었을 가능성이 높습니다.
로그를 기록하는 과정인 ‘로깅(logging)’은 보편화되었기 때문에, 많은 프로그래밍 언어의 기본 라이브러리에 로깅 기능이 내장되어 있습니다. 데이터를 로깅하는 기본 ‘로거(logger)’가 없는 환경에는 강력하고 유연한 서드파티 대안이 존재합니다. 또한 스택 전체에서 로그를 형식화, 제어, 캡처 및 해석하는 데 도움을 주는 많은 도구들이 나와 있습니다.
로그의 단점은 무엇일까요?
로그가 ‘비정형’ 텍스트란 말을 앞서 했습니다. 그것이 바로 텔레메트리 유형인 로그의 문제점입니다. 로그는 긴 텍스트로 구성되어 있기 때문에, 일관성이나 계획 없이 이것 저것 던져 넣어 둔 잡동사니 서랍과 같습니다. 명확한 의미를 알 수 있는 메트릭 값이나, 스키마와 관계가 잘 알려진 트레이스 스팬과 비교하면, 로그는 모든 것이 뒤죽박죽인 상태인 것처럼 보입니다.
명확한 체계가 없어서 가장 관심 있는 로그의 포맷을 제어할 수 없다는 점은 문제를 가중시킵니다. 웹 서버이든 클라우드 제공업체이든, 결과물의 포맷과 콘텐츠는 그냥 보이는 그대로가 전부입니다.
로그는 또한 용량이 클 수 있습니다. 쉽게 생성된다는 말은 스택의 모든 수준에서 엄청난 양의 텍스트가 생성될 수 있다는 것을 의미합니다. 주의하지 않으면 디스크 공간이 부족할 때 일부 디버그 로깅으로 인해 로컬 애플리케이션에 문제가 발생할 수도 있습니다. 엄청난 양의 데이터를 수집해 저장하고 쿼리하기란 결코 쉽지 않은 일입니다.
로그를 어떻게 더 효과적으로 활용할 수 있을까요?
로그의 장단점을 고려할 때, 어떻게 로깅을 강화하고 로그 데이터를 최대한 활용할 수 있을까요? 뉴렐릭 로깅의 몇 가지 주요 기능을 통해, 로그에서 기존 계측을 뛰어넘는 인사이트를 확보하는 방법을 알아봅니다.
구조화된 로깅
위에서 로그를 잡동사니 서랍에 비유했지만, 서랍을 엉망진창인 상태로 둘 필요는 없습니다. 제어할 수 있는 애플리케이션에서 로그가 생성되는 경우, 구조화된 로깅을 활용하면 말끔하게 정리정돈하는 것이 가능합니다.
가장 일반적인 형태의 경우, 원시 텍스트 줄이 아니라 JSON 데이터를 내보내어 로그를 명확하게 만드는 것입니다. JSON은 이후 프로세서에 도움이 되는 표준 속성을 가질 수 있습니다. 그렇기 때문에 다음과 같은 로그가 아니라
Something happened!!!무슨 일이 일어났는지 파악하는 데 필요한 많은 데이터를 얻을 수 있습니다.
{
"appName": "My Application",
"hostname": "myhost.example.com",
"level": "ERROR",
"message": "Something happened!!!"
}보통 이러한 로그 포맷은 웹 프레임워크와 통합될 수 있기 때문에, 추가 값을 설정하거나 JSON을 직접 작성할 필요가 없습니다. Rails에서 사용되는 lograge와 semantic_logger가 좋은 예입니다.
로그와 다른 데이터의 연결
로그에 구조와 의미를 추가하는 기능을 사용하면, 온프레미스 ELK(Elasticsearch, Logstash 및 Kibana) 스택이나 뉴렐릭 등 서비스형 소프트웨어 공급업체가 제공하는 중앙화된 시스템에서 작업하는 것이 더 쉬워집니다. 애플리케이션 개발자의 경우, 애플리케이션에서 로그를 필터링하는 것은 모래사장에서 바늘을 찾는 첫 번째 단계입니다.
뉴렐릭 APM 에이전트에는 자동으로 메타데이터를 추가하는 로그 전달 기능이 내장되어, 애플리케이션뿐만 아니라 트레이스와 스팬(시스템의 개별 요청)도 연결합니다. 이를 통해, 특정 오류 트레이스와 함께 발생한 로그를 확인할 수 있습니다.
스택 트레이스와 오류의 기타 속성이 전체 스토리를 알려주지 않는 경우, 로그가 있으면 필요한 인사이트를 얻을 수 있습니다.
참고: 여기서는 APM과 로깅 연결에 중점을 두지만, 뉴렐릭의 거의 모든 엔터티에는 호스트, 모든 쿠버네티스 오브젝트, 클라우드 통합 등 연관된 로그 데이터가 있을 수 있습니다.
모든 조직이 APM 에이전트 전달을 사용하지는 않습니다. 예를 들어, 쿠버네티스 클러스터 내에 또는 중앙화된 syslog 서버에 로그 전달 솔루션이 이미 구성되어 있을 수 있습니다. 로그를 보내는 APM 에이전트가 아니라 다른 도구를 사용하는 경우에도, 로컬 데코레이션 옵션을 통해 로그와 APM 간의 연결을 활용할 수 있습니다. 이 옵션을 활성화하면 필요한 메타데이터를 확보할 수 있도록 기록된 로그를 수정하여 뉴렐릭 UI에 연결된 로그를 확인하고 모든 장점을 활용할 수 있습니다.
로그 구문 분석
로그가 JSON 포맷이 아니라 텍스트 속에 숫자들이 파묻혀 있는 경우라면 어떻게 할까요? 예를 들어 일부 Java 앱에는 다음과 같은 메시지를 기록하고 자체 수명 주기 시스템을 갖춘 여러 내부 ‘서비스’ 클래스가 있습니다.
2023-10-04 23:10:49,612{UTC} [main] INFO c.n.a.OrderedServiceManager - Started AccountClientAutoService [RUNNING] in 519 milliseconds줄 맨 끝에 나와 있는 타이밍 정보는 훌륭한 메트릭이나 이벤트가 될 수 있지만 로그 메시지 속에 파묻혀 있습니다. 그래도 원하는 사항을 쿼리하는 것이 가능합니다.
이 경우 로깅 UI를 통해 관심 있는 줄을 찾는 것부터 시작합니다. 그러면 키워드와 기본 속성 값 쌍을 쉽게 검색할 수 있습니다. ‘Query logs(로그 쿼리)’ 버튼 옆에 ‘NRQL’ 버튼이 있습니다. 이 버튼을 클릭하면 쿼리 빌더로 이동합니다. 여기에서 현재 로그 세트를 찾는 데 사용된 NRQL(뉴렐릭 쿼리 언어) 쿼리를 볼 수 있습니다.
SELECT `message`
FROM Log
WHERE `container_name` = 'log-parser-consumer'
AND allColumnSearch('Started', insensitive: true)
AND allColumnSearch('RUNNING', insensitive: true)참고: allColumnSearch 호출은 로그나 기타 뉴렐릭 데이터베이스(NRDB) 이벤트에서 값이 어디에 있는지 모르는 경우 모든 속성을 검색하는 데 유용한 기능입니다. 그러나 광범위한 검색이 필요하지 않은 경우 개별 필드에 대해 =, LIKE, 또는 유사 명령어를 수행하면 쿼리가 빨라집니다. 예를 들어, WHERE message LIKE '%Started%RUNNING%'를 사용하면 더 효과적으로 위의 결과를 얻을 수 있습니다.
관심 있는 메시지로 필터링되었으므로, NRQL의 최신 기능 중 하나인 aparse를 사용해 메시지 텍스트를 분리합니다. 문서 내용을 옮겨 놓지는 않겠지만, 위의 메시지에 aparse를 사용하면 타이밍 정보를 추출할 수 있습니다.
SELECT aparse(`message`, '% in * milli%') as startupDuration
FROM Log
WHERE `container_name` = 'log-parser-consumer'
AND allColumnSearch('Started', insensitive: true)
AND allColumnSearch('RUNNING', insensitive: true)좋습니다. 이제 결과에 startupDuration이라는 속성이 생겼습니다. 클래스 이름도 필요합니다. 이를 위해서는 aparse와 WITH 블록을 사용합니다.
WITH aparse(`message`, '%Started * [% in * milli%')
AS (service, startupDuration)
SELECT service, startupDuration
FROM Log
WHERE `container_name` = 'log-parser-consumer'
AND allColumnSearch('Started', insensitive: true)
AND allColumnSearch('RUNNING', insensitive: true)이제 서비스와 그 타이밍이 포함된 표가 표시됩니다. 여기에 수학을 좀 적용해 봅니다. 서비스별로 그룹화하고 startupDuration의 평균값을 계산해 각 클래스의 성능을 확인해 보는 것입니다.
WITH aparse(`message`, '%Started * [% in * milli%')
AS (service, startupDuration)
SELECT average(startupDuration)
FROM Log
WHERE `container_name` = 'log-parser-consumer'
AND allColumnSearch('Started', insensitive: true)
AND allColumnSearch('RUNNING', insensitive: true)
FACET service그런데 평균 열이 비어 있습니다. 왜 그럴까요? 로그에서는 모든 것이 텍스트로 되어 있다는 것을 기억하시나요? 함수 호출을 하면 간단하게 이 문제를 해결할 수 있습니다.
WITH aparse(`message`, '%Started * [% in * milli%')
AS (service, startupDuration)
SELECT average(numeric(startupDuration))
FROM Log
WHERE `container_name` = 'log-parser-consumer'
AND allColumnSearch('Started', insensitive: true)
AND allColumnSearch('RUNNING', insensitive: true)
FACET service장기간 사용의 경우 뉴렐릭의 이벤트-메트릭 기능을 사용해 이 데이터를 애플리케이션에서 직접 기록하거나 실제 메트릭으로 기록하는 것이 좋습니다. 대안으로, 데이터가 인제스트될 때 값을 자체 속성으로 추출하는 구문 분석 규칙을 만들면 나중에 더 쉽게 쿼리를 할 수 있습니다.
어느 쪽을 사용하든, 이미 보유한 로그를 사용해 쉽게 작업을 수행할 수 있습니다. 그리고 로그는 NRDB의 또 다른 데이터이기 때문에, 알림, 대시보드 또는 서비스 수준 목표(SLO) 정의 같은 뉴렐릭의 다른 부분에서도 이 결과를 사용할 수 있습니다.
시간에 따라 로그 상호 연관
임의 로그와 NRQL이 가진 또 다른 역량을 살펴봅니다. 이전과 마찬가지로, 애플리케이션의 시작 시간에 관심이 있다고 가정해 보겠습니다. 그런데 이번에는 시간이 포함된 줄이 하나도 없습니다. 대신, 시간 범위를 알길 원하는 두 개의 줄이 있습니다. 첫 번째 줄은 앱이 부팅된 시점이고, 다른 줄은 트래픽을 받기 시작한 시점입니다.
보다 자세히 설명하기 위해 뉴렐릭 로깅 팀의 예를 들어 보겠습니다! 기본 인제스트 서비스가 부팅되면 두 가지 다른 줄이 표시됩니다.
- 첫 번째 줄은
starting log-parser-consumer로 Java 애플리케이션이 시작되었음을 나타냅니다. - 두 번째 줄은 Kafka 소비자(
LogsToParseKafkaConsumerAutoService)의 클래스 이름을 호출하며, 그것이 실행 중이라는 사실을 알려줍니다.
starting log-parser-consumer
... lots of other work done to start up...
2023-10-04 23:26:52,429{UTC} [main] INFO c.n.a.OrderedServiceManager - Started LogsToParseKafkaConsumerAutoService [RUNNING] in 0 milliseconds먼저 해당 줄만 찾도록 다음과 같은 쿼리를 작성합니다.
SELECT message
FROM Log
WHERE `container_name` = 'log-parser-consumer' AND
(message LIKE '%starting log-parser-consumer%' OR
message LIKE '%Started%LogsToParseKafkaConsumerAutoService%RUNNING%')
LIMIT MAX다음에는 각 애플리케이션이 시작할 때마다 패싯을 할 고유한 데이터가 필요합니다. 뉴렐릭의 구조화된 로깅에서 생성되는 고유한 pod_name이 이 부분에서 유용합니다. 다음 쿼리는 관심 있는 두 개의 메시지를 파드별로 그룹화하여 표시하는 것이 목표입니다. 한 열은 시작 메시지를, 다른 열은 종료 메시지를 표시합니다.
SELECT
filter(latest(message), WHERE message LIKE '%log-parser%') AS firstLog,
filter(latest(message), WHERE message NOT LIKE '%log-parser%') AS secondLog
FROM Log
WHERE `container_name` = 'log-parser-consumer' AND
(message LIKE '%starting log-parser-consumer%' OR
message LIKE '%Started%LogsToParseKafkaConsumerAutoService%RUNNING%')
FACET pod_name
LIMIT MAX원하는 내용이라는 것을 알 수 있습니다. 각 pod_name 별로 한 행에 두 줄이 표시됩니다.
NRQL에는 최신 함수가 도입되었습니다. 바로 데이터 세트에서 최신 값을 가져오는 집계 함수입니다. 메시지를 추출해 작동하고 있는게 확인되면, 필요한 것은 latest(timestamp)입니다. 시작 타임스탬프와 종료 타임스탬프에 계산을 하면, 로그 스트림에 있는 임의의 두 지점 사이의 타이밍 데이터를 얻을 수 있습니다!
SELECT
filter(latest(timestamp), WHERE message NOT LIKE '%log-parser-consumer%') -
filter(latest(timestamp), WHERE message LIKE '%log-parser-consumer%') as startupDuration
FROM Log
WHERE `container_name` = 'log-parser-consumer' AND
(message LIKE '%starting log-parser-consumer%' OR
message LIKE '%Started%LogsToParseKafkaConsumerAutoService%RUNNING%')
FACET pod_name
LIMIT MAX결론
숫자로 된 것을 측정하려는 경우 가장 좋은 방법은 메트릭을 사용하는 것입니다. 하지만 로그만 있더라도 절망할 필요는 없습니다. 뉴렐릭의 로깅 팀은 위에 설명된 방법을 여러 차례 사용해 추적하려는 새로운 성능 데이터를 찾고, 오류 소스를 쉽게 식별하며, 알림과 모니터링을 개선했습니다. 로그를 제대로 활용하면 시스템에 대해 전례없는 가시성을 확보할 수 있습니다.
이 블로그에 표현된 견해는 저자의 견해이며 반드시 New Relic의 견해를 반영하는 것은 아닙니다. 저자가 제공하는 모든 솔루션은 환경에 따라 다르며 New Relic에서 제공하는 상용 솔루션이나 지원의 일부가 아닙니다. 이 블로그 게시물과 관련된 질문 및 지원이 필요한 경우 Explorers Hub(discuss.newrelic.com)에서만 참여하십시오. 이 블로그에는 타사 사이트의 콘텐츠에 대한 링크가 포함될 수 있습니다. 이러한 링크를 제공함으로써 New Relic은 해당 사이트에서 사용할 수 있는 정보, 보기 또는 제품을 채택, 보증, 승인 또는 보증하지 않습니다.
