Aurora PostgreSQL Limitless Database의 PostgreSQL 로그에서 분산 쿼리 추적 - Amazon Aurora
추적 ID쿼리 추적 사용로그 예제

Aurora PostgreSQL Limitless Database의 PostgreSQL 로그에서 분산 쿼리 추적

분산 쿼리 추적은 Aurora PostgreSQL Limitless Database에서 PostgreSQL 로그의 쿼리를 추적하고 상호 연관시키는 도구입니다. Aurora PostgreSQL에서는 트랜잭션 ID를 사용하여 트랜잭션을 식별합니다. 그러나 Aurora PostgreSQL Limitless Database에서는 트랜잭션 ID가 다양한 라우터에서 반복될 수 있습니다. 따라서 Limitless Database에서는 대신 추적 ID를 사용하는 것이 좋습니다.

주요 사용 사례는 다음과 같습니다.

  • rds_aurora.limitless_get_last_trace_id() 함수를 사용하여 현재 세션에서 마지막으로 실행된 쿼리의 고유한 추적 ID를 찾습니다. 그런 다음 해당 추적 ID를 사용하여 Amazon CloudWatch Logs에서 DB 클러스터 로그 그룹을 검색하여 모든 관련 로그를 찾습니다.

    log_min_messages 및 log_min_error_statement 파라미터를 함께 사용하여 인쇄된 로그 볼륨을 제어하고 추적 ID가 포함된 문을 인쇄할 수 있습니다.

  • log_min_duration_statement 파라미터를 사용하여 모든 쿼리가 실행 기간 및 추적 ID를 인쇄하는 기준이 되는 실행 시간을 결정합니다. 그런 다음 CloudWatch Logs의 DB 클러스터 로그 그룹에서 이 실행 시간을 검색하여 병목 노드와 플래너 최적화 노력을 확인할 수 있습니다.

    log_min_duration_statement 파라미터는 log_min_messages 및 log_min_error_statement 파라미터의 값에 관계없이 모든 노드에 대해 추적 ID를 활성화합니다.

추적 ID

이 기능의 핵심은 추적 ID라고 하는 고유 식별자입니다. 추적 ID는 PostgreSQL 로그의 STATEMENT 로그 줄에 추가된 31자리 문자열로, 특정 쿼리 실행과 관련된 로그를 상호 연관시키기 위한 정확한 식별자 역할을 합니다. 대표적인 예는 1126253375719408504000000000011 및 1126253375719408495000000000090입니다.

추적 ID는 다음으로 구성됩니다.

  • 트랜잭션 식별자 - 트랜잭션을 고유하게 식별하는 처음 20자리입니다.

  • 명령 식별자 - 트랜잭션 내의 개별 쿼리를 나타내는 처음 30자리입니다.

    명시적 트랜잭션 블록 내에서 4,294,967,294개 이상의 쿼리가 실행되는 경우 명령 식별자는 1로 래핑됩니다. 이 경우 PostgreSQL 로그에 다음 LOG 메시지가 표시됩니다.

    wrapping around the tracing ID back to 1 after running 4294967294 (4.2 billion or 2^32-2) queries inside of an explicit transaction block

  • 노드 유형 식별자 - 노드가 코디네이터 라우터(1) 또는 참가자 노드(0) 중 무엇으로 작동하는지 나타내는 마지막 숫자입니다.

다음 예시에서는 추적 ID의 구성 요소를 보여줍니다.

  • 1126253375719408504000000000011:

    • 트랜잭션 식별자 - 1126253375719408504

    • 명령 식별자 - 112625337571940850400000000001은 트랜잭션 블록의 첫 번째 명령을 나타냅니다.

    • 노드 유형 식별자 - 1은 코디네이터 라우터를 나타냅니다.

  • 1126253375719408495000000000090:

    • 트랜잭션 식별자 - 1126253375719408495

    • 명령 식별자 - 112625337571940849500000000009는 트랜잭션 블록의 9번째 명령을 나타냅니다.

    • 노드 유형 식별자 - 0은 참가자 노드를 나타냅니다.

쿼리 추적 사용

쿼리 추적을 사용하려면 다음 작업을 수행합니다.

  1. 추적이 활성화되어 있는지 확인합니다.

    다음 명령을 사용하여 확인할 수 있습니다.

    SHOW rds_aurora.limitless_log_distributed_trace_id;

    기본적으로 활성화(on)되어 있습니다. 활성화되지 않은 경우 다음 명령을 사용하여 설정합니다.

    SET rds_aurora.limitless_log_distributed_trace_id = on;

  2. 로그 심각도 수준을 구성하여 인쇄된 로그 볼륨을 제어합니다.

    로그 볼륨은 log_min_messages 파라미터로 제어됩니다. log_min_error_statement 파라미터는 추적 ID가 있는 STATEMENT 줄을 인쇄하는 데 사용됩니다. 둘 다 기본적으로 ERROR로 설정됩니다. 다음 명령을 사용하여 확인할 수 있습니다.

    SHOW log_min_messages;
SHOW log_min_error_statement;

    심각도 수준을 업데이트하고 현재 세션의 STATEMENT 줄을 인쇄하려면 다음 심각도 수준 중 하나와 함께 다음 명령을 사용합니다.

    SET log_min_messages = 'DEBUG5 | DEBUG4 | DEBUG3 | DEBUG2 | DEBUG1 | INFO | NOTICE | WARNING | ERROR | LOG | FATAL | PANIC';
SET log_min_error_statement = 'DEBUG5 | DEBUG4 | DEBUG3 | DEBUG2 | DEBUG1 | INFO | NOTICE | WARNING | ERROR | LOG | FATAL | PANIC';

    예시:

    SET log_min_messages = 'WARNING';
SET log_min_error_statement = 'WARNING';

  3. 특정 실행 시간을 초과하는 로그에서 추적 ID 인쇄를 활성화합니다.

    log_min_duration_statement 파라미터를 최소 쿼리 실행 시간으로 변경할 수 있습니다. 이 시간을 초과하면 쿼리가 DB 클러스터 전반의 추적 ID와 함께 실행 기간이 포함된 로그 줄을 인쇄합니다. 이 파라미터는 기본적으로 -1로 설정되어 있으며 비활성화되어 있다는 뜻입니다. 다음 명령을 사용하여 확인할 수 있습니다.

    SHOW log_min_duration_statement;

    0으로 변경하면 DB 클러스터 전체의 모든 쿼리에 대한 로그에 기간 및 추적 ID를 인쇄합니다. 다음 명령을 사용하여 현재 세션에 대해 0으로 설정할 수 있습니다.

    SET log_min_duration_statement = 0;

  4. 추적 ID를 가져옵니다.

    쿼리를 실행한 후(명시적 트랜잭션 블록 내에서도) rds_aurora.limitless_get_last_trace_id 함수를 직접 호출하여 마지막 쿼리 실행의 추적 ID를 가져옵니다.

    SELECT * FROM rds_aurora.limitless_get_last_trace_id();

    이 함수는 트랜잭션 식별자와 명령 식별자를 반환합니다. 노드 유형 식별자는 반환되지 않습니다.

    => SELECT * FROM customers;
 customer_id | fname | lname 
-------------+-------+-------
(0 rows)

=> SELECT * FROM rds_aurora.limitless_get_last_trace_id();
 transaction_identifier |       command_identifier       
------------------------+--------------------------------
 10104661421959001813   | 101046614219590018130000000001
(1 row)

    추적 ID가 없으므로 함수는 분산되지 않은 쿼리에 대해 빈 줄을 반환합니다.

    => SET search_path = public;
SET

=> SELECT * FROM rds_aurora.limitless_get_last_trace_id();
 transaction_identifier | command_identifier 
------------------------+--------------------
                        | 
(1 row)
    참고

    VACUUM 및 ANALYZE 쿼리의 경우 기간 문은 추적 ID와 함께 로깅되지 않습니다. 따라서 limitless_get_last_trace_id()는 추적 ID를 반환하지 않습니다. VACUUM 또는 ANALYZE가 장기 실행 작업인 경우 다음 쿼리를 사용하여 해당 작업에 대한 추적 ID를 가져올 수 있습니다.

    SELECT * FROM rds_aurora.limitless_stat_activity 
WHERE distributed_tracing_id IS NOT NULL;

    마지막 추적 ID를 찾기 전에 서버가 중지되면 PostgreSQL 로그를 수동으로 검색하여 실패 직전의 로그에서 추적 ID를 찾아야 합니다.

  5. CloudWatch를 사용하여 DB 클러스터 로그에서 추적 ID를 검색합니다.

    다음 예시와 같이 CloudWatch Insights를 사용하여 DB 클러스터의 로그 그룹을 쿼리합니다.

    • 특정 트랜잭션 식별자 및 그 안에서 실행되는 모든 명령에 대한 쿼리:

      fields @timestamp, @message
| filter @message like /10104661421959001813/
| sort @timestamp desc

    • 특정 명령 식별자에 대한 쿼리:

      fields @timestamp, @message
| filter @message like /101046614219590018130000000001/
| sort @timestamp desc

  6. 분산 쿼리에서 생성된 DB 클러스터의 모든 로그를 검사합니다.

로그 예제

다음 예시는 쿼리 추적 사용을 보여줍니다.

오류가 발생하기 쉬운 쿼리에 대한 로그 상호 연관

이 예시에서 TRUNCATE 명령은 해당 테이블이 없으면 customers 테이블에서 실행됩니다.

쿼리 추적 없음

코디네이터 라우터의 PostgreSQL 로그 파일:

2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[27503]:ERROR: failed to execute remote query
2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[27503]:DETAIL: relation "public.customers" does not exist
2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[27503]:CONTEXT: remote SQL command: truncate public.customers;
2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[27503]:STATEMENT: truncate customers;

참가자 샤드의 PostgreSQL 로그 파일:

2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[ 27503]:ERROR: failed to execute remote query
2023-09-26 04:03:19 UTC:[local]: postgres@postgres_limitless:[ 27503]:STATEMENT: truncate customers;

이러한 로그는 일반적인 로그입니다. DB 클러스터 전체에서 쿼리를 쉽게 상호 연관시키는 데 필요한 정확한 식별자가 부족합니다.

쿼리 추적 있음

코디네이터 라우터의 PostgreSQL 로그 파일:

2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:ERROR: failed to execute remote query
2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:DETAIL: relation "public.customers" does not exist
2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:CONTEXT: remote SQL command: truncate public.customers;
2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:STATEMENT: /* tid = 1126253375719408502700000000011 */ truncate customers;

참가자 샤드의 PostgreSQL 로그 파일:

2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:ERROR:  failed to execute remote query
2023-09-26 04:03:19 UTC:[local]:postgres@postgres_limitless:[27503]:STATEMENT:  /* tid = 1126253375719408502700000000010 */ truncate customers;

쿼리 추적이 있는 경우 각 로그 라인에 31자리 고유 식별자가 추가됩니다. 여기서 1126253375719408502700000000011 및 1126253375719408502700000000010은 각각 코디네이터 및 참가자 노드의 추적 ID를 나타냅니다.

  • 트랜잭션 식별자 - 11262533757194085027

  • 명령 식별자 –112625337571940850270000000001

  • 노드 유형 식별자 - 마지막 자리인 1 또는 0은 각각 코디네이터 라우터와 참가자 노드를 나타냅니다.

로그를 상호 연관시켜 다양한 노드에서 쿼리 실행 시간 찾기

이 예시에서 log_min_duration_statement 파라미터는 모든 쿼리의 기간을 인쇄하기 위해 0으로 업데이트되었습니다.

쿼리 추적 없음
2024-01-15 07:28:46 UTC:[local]:postgres@postgres_limitless:[178322]:LOG: duration: 12.779 ms statement: select * from customers;
쿼리 추적 있음

코디네이터 라우터의 PostgreSQL 로그 파일:

2024-01-15 07:32:08 UTC:[local]:postgres@postgres_limitless:[183877]:LOG: duration: 12.618 ms statement: /* tid = 0457669566240497088400000000011 */ select * from customers;

참가자 샤드의 PostgreSQL 로그 파일:

2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.279 ms statement: /* tid = 0457669566240497088400000000010 */ START TRANSACTION ISOLATION LEVEL READ COMMITTED
2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.249 ms parse <unnamed>: SELECT customer_id, fname, lname FROM public.customers
2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.398 ms bind <unnamed>/c1: SELECT customer_id, fname, lname FROM public.customers
2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.019 ms execute <unnamed>/c1: SELECT customer_id, fname, lname FROM public.customers
2024-01-15 07:32:08 UTC:localhost(46358):postgres@postgres_limitless:[183944]:LOG: duration: 0.073 ms statement: /* tid = 0457669566240497088400000000010 */ COMMIT TRANSACTION