지난 글에서 elapsed 필터로 멀티 라인 구조를 갖는 하나의 트랜잭션 실행 시간을 구해봤는데 멀티 코어가 멀티 라인 로그를 나눠 처리하는 로그스태시의 동작 방식 때문에 잘 되지 않았다. 그렇다고 싱글 코어를 쓰자니 로그양이 너무 많고(..)

test.log

1
2
[08:00:37.410] StartJob
[08:00:39.235] EndJob

멀티 라인 구조를 싱글 라인으로 바꿔보자. Logstash codec 플러그인 중 multiline은 서로 다른 시점에 발생한 여러 개의 로그를 특정 조건으로 합쳐준다. 다음은 message 필드에 'EndJob' 패턴이 존재하면 직전(previous)에 발생한 message 필드에 추가하는 설정이며, 결과적으로 동일 트랜잭션의 시작과 끝을 알리는 로그를 하나로 합쳐준다.

1
2
3
4
5
6
7
8
9
10
11
input {
 file {
  path => "D:/test.log"
  start_position => "beginning"
  sincedb_path => "nul"
  codec => multiline {
   pattern => "EndJob"
   what => "previous"
  }
 }
}

다음은 실행 결과. 멀티 코어가 줄 단위로 로그를 나눠 처리하는 과정에서 multiline 작업도 누수가 발생하지 않을까 싶었는데, 로그를 늘려도 누수는 발생하지 않는다. multiline 작업 트랜잭션이 코어 단위로 이루어지는 듯?

1
2
3
4
5
6
7
8
9
10
{
"@version" => "1",
"@timestamp" => 2020-02-27T12:55:23.224Z,
"tags" => [
[0] "multiline"
],
"path" => "D:/test.log",
"message" => "[08:00:37.410] StartJob\r\n[08:00:39.235] EndJob\r",
"host" => "MHKANG"
}

이제 시작과 종료 시간을 추출하면 됨. 다음은 dissect 플러그인을 이용해서 시간값을 추출하는 설정.

1
2
3
4
5
filter {
 dissect {
  mapping => { "message" => "[%{start_time}]%{}[%{end_time}]%{}" }
 }
}

실행 결과는 다음과 같다.

1
2
3
4
5
6
7
8
9
10
11
12
{
"@version" => "1",
"@timestamp" => 2020-02-27T13:04:16.713Z,
"tags" => [
[0] "multiline"
],
"path" => "D:/test.log",
"message" => "[08:00:37.410] StartJob\r\n[08:00:39.235] EndJob\r",
"start_time" => "08:00:37.410",
"host" => "MHKANG",
"end_time" => "08:00:39.235"
}

이제 end_time에서 start_time을 빼면 됨. 그런데 추출된 필드의 데이터 유형이 '문자열'이라 산술 연산을 할 수 없다. 데이터 유형을 숫자로 바꿔주면 될까? 계산 대상은 무려 '시간'이다. 시간, 분, 초 등 시간 단위를 반영한 계산이 필요하다는 얘기.

대충 생각해도 ①각 시간 단위를 쪼갠 후 ②숫자 유형으로 바꾼 다음 ③다시 각 단위를 초 단위로 바꾸고 ④그걸 더한 필드끼리 계산하는 과정이 필요해보인다(..)

그런데 이 어려운 걸

ruby 플러그인이 해냄. 다음은 Time.parse() 함수를 이용해서 문자 유형으로 저장된 시간 필드를 시간 유형으로 변환 후, 시간차를 계산하는 설정.

1
2
3
4
5
6
7
8
filter {
 dissect {
  mapping => { "message" => "[%{start_time}]%{}[%{end_time}]%{}" }
 }
 ruby {
  code => "event.set('delay_time', Time.parse(event.get('end_time')) - Time.parse(event.get('start_time')) )"
 }
}

실행 결과는 다음과 같다.

1
2
3
4
5
6
7
8
9
10
11
12
13
{
"@version" => "1",
"@timestamp" => 2020-02-27T13:19:16.779Z,
"tags" => [
[0] "multiline"
],
"path" => "D:/test.log",
"message" => "[08:00:37.410] StartJob\r\n[08:00:39.235] EndJob\r",
"start_time" => "08:00:37.410",
"delay_time" => 1.825,
"host" => "MHKANG",
"end_time" => "08:00:39.235"
}

ruby 만세!