Tracciamento distribuito delle query nei log di PostgreSQL in Aurora PostgreSQL Limitless Database - Amazon Aurora

Le traduzioni sono generate tramite traduzione automatica. In caso di conflitto tra il contenuto di una traduzione e la versione originale in Inglese, quest'ultima prevarrà.

Tracciamento distribuito delle query nei log di PostgreSQL in Aurora PostgreSQL Limitless Database

Il tracciamento distribuito delle query è uno strumento per tracciare e correlare le query nei log di PostgreSQL su Aurora PostgreSQL Limitless Database. In Aurora PostgreSQL, le transazioni vengono identificate mediante il relativo ID. Tuttavia, in Aurora PostgreSQL Limitless Database, l’ID della transazione può essere ripetuto su vari router. È quindi consigliabile ricorrere piuttosto all’ID di tracciamento in Limitless Database.

Di seguito sono riportati i principali casi d’uso:

  • Utilizza la funzione rds_aurora.limitless_get_last_trace_id() per trovare l’ID di tracciamento univoco dell’ultima query eseguita nella sessione corrente. Quindi cerca nel gruppo di log del cluster di database in Amazon CloudWatch Logs utilizzando quell’ID di tracciamento per trovare tutti i log correlati.

    Puoi utilizzare i parametri log_min_error_statement e log_min_messages insieme per controllare il volume dei log stampati e stampare un’istruzione che contiene l’ID di tracciamento.

  • Utilizza il parametro log_min_duration_statement per determinare il tempo di esecuzione trascorso il quale tutte le query stampano la durata dell’esecuzione e l’ID di tracciamento. Puoi cercare questo tempo di esecuzione nel gruppo di log del cluster di database in CloudWatch Logs e utilizzarlo per determinare i nodi dei colli di bottiglia e gli sforzi di ottimizzazione del pianificatore.

    Il parametro log_min_duration_statement abilita l’ID di tracciamento per tutti i nodi, indipendentemente dai valori di log_min_messages e log_min_error_statement.

ID di tracciamento

L’elemento fondamentale di questa funzionalità è un identificatore univoco noto come ID di tracciamento. L’ID di tracciamento è una stringa di 31 cifre aggiunta alle righe di log STATEMENT dei log di PostgreSQL, che funge da identificatore esatto per correlare i log relativi all’esecuzione di una query specifica. Alcuni esempi sono 1126253375719408504000000000011 e 1126253375719408495000000000090.

L’ID di tracciamento è costituito dai seguenti elementi:

  • Identificatore della transazione: le prime 20 cifre, che identificano in modo univoco la transazione.

  • Identificatore del comando: le prime 30 cifre, che indicano una singola query all’interno di una transazione.

    Se all’interno di un blocco di transazione esplicito vengono eseguite più di 4.294.967.294 query, l’identificatore del comando torna a 1. Quando questo accade, ti viene notificato dal seguente messaggio di LOG nel log di PostgreSQL:

    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
  • Identificatore del tipo di nodo: l’ultima cifra, che indica se il nodo funziona come router coordinatore (1) o nodo partecipante (0).

Gli esempi seguenti illustrano i componenti dell’ID di tracciamento:

  • 1126253375719408504000000000011:

    • Identificatore della transazione: 1126253375719408504

    • Identificatore del comando: 112625337571940850400000000001 indica il primo comando nel blocco di transazione

    • Identificatore del tipo di nodo: 1 indica un router coordinatore

  • 1126253375719408495000000000090:

    • Identificatore della transazione: 1126253375719408495

    • Identificatore del comando: 112625337571940849500000000009 indica il nono comando nel blocco di transazione

    • Identificatore del tipo di nodo: 0 indica un nodo partecipante

Utilizzo del tracciamento delle query

Per utilizzare il tracciamento delle query, esegui queste attività:

  1. Assicurati che il tracciamento sia abilitato.

    Per verificare, utilizza il comando seguente:

    SHOW rds_aurora.limitless_log_distributed_trace_id;

    È abilitato per impostazione predefinita (on). Se non è abilitato, impostalo utilizzando il comando seguente:

    SET rds_aurora.limitless_log_distributed_trace_id = on;
  2. Controlla il volume dei log stampati configurando il livello di gravità del log.

    Il volume dei log è controllato dal parametro log_min_messages. Il parametro log_min_error_statement viene utilizzato per stampare la riga STATEMENT con l’ID del tracciamento. L’impostazione predefinita di entrambi è ERROR. Per verificare, utilizza i comandi seguenti:

    SHOW log_min_messages; SHOW log_min_error_statement;

    Per aggiornare il livello di gravità e stampare la riga STATEMENT per la sessione corrente, utilizza i seguenti comandi con uno di questi livelli di gravità:

    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';

    Per esempio:

    SET log_min_messages = 'WARNING'; SET log_min_error_statement = 'WARNING';
  3. Abilita la stampa dell’ID di tracciamento nei log una volta superato un tempo di esecuzione specifico.

    Il parametro log_min_duration_statement può essere modificato impostando il tempo minimo di esecuzione della query oltre il quale la query stampa una riga del log con la durata dell’esecuzione insieme agli ID di tracciamento nel cluster di database. L’impostazione predefinita di questo parametro è -1, il che significa che è disabilitato. Per verificare, utilizza il comando seguente:

    SHOW log_min_duration_statement;

    Se si imposta il parametro su 0, vengono stampati la durata e l’ID di tracciamento nei log per ogni query nel cluster di database. È possibile impostare il parametro su 0 per la sessione corrente utilizzando il comando seguente:

    SET log_min_duration_statement = 0;
  4. Ottieni l’ID di tracciamento.

    Dopo aver eseguito una query (anche all’interno di un blocco di transazione esplicito), chiama la funzione rds_aurora.limitless_get_last_trace_id per ottenere l’ID di tracciamento dell’ultima esecuzione della query:

    SELECT * FROM rds_aurora.limitless_get_last_trace_id();

    Questa funzione restituisce l’identificatore della transazione e l’identificatore del comando. Non restituisce l’identificatore del tipo di nodo.

    => 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)

    La funzione restituisce una riga vuota per le query non distribuite, in quanto non dispongono di un ID di tracciamento.

    => SET search_path = public; SET => SELECT * FROM rds_aurora.limitless_get_last_trace_id(); transaction_identifier | command_identifier ------------------------+-------------------- | (1 row)
    Nota

    Per le query VACUUM e ANALYZE, l’istruzione di durata non viene registrata con l’ID di tracciamento. Pertanto, limitless_get_last_trace_id() non restituisce l’ID di tracciamento. Se VACUUM o ANALYZE è un’operazione di lunga durata, puoi ottenere il relativo ID di tracciamento utilizzando la seguente query:

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

    Se il server si ferma prima che sia possibile trovare l’ultimo ID di tracciamento, sarà necessario eseguire una ricerca manuale nei log di PostgreSQL per individuare gli ID di tracciamento nei log precedenti all’errore.

  5. Cerca l’ID di tracciamento nei log del cluster di database utilizzando CloudWatch.

    Utilizza CloudWatch Insights per interrogare il gruppo di log del cluster di database, come illustrato negli esempi seguenti.

    • Esegui una query per un particolare identificatore della transazione e tutti i comandi che vengono eseguiti al suo interno:

      fields @timestamp, @message | filter @message like /10104661421959001813/ | sort @timestamp desc
    • Query per un particolare identificatore del comando:

      fields @timestamp, @message | filter @message like /101046614219590018130000000001/ | sort @timestamp desc
  6. Esamina tutti i log del cluster di database generati dalla query distribuita.

Esempi di log

I seguenti esempi mostrano l’utilizzo del tracciamento delle query.

Correlazione dei log per le query soggette a errori

In questo esempio, il comando TRUNCATE viene eseguito sulla tabella customers quando questa non esiste.

Senza tracciamento delle query

File di log PostgreSQL sul router coordinatore:

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;

File di log PostgreSQL su uno shard partecipante:

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;

Questi log sono tipici. Mancano degli identificatori precisi necessari per correlare facilmente le query all’interno del cluster di database.

Con tracciamento delle query

File di log PostgreSQL sul router coordinatore:

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;

File di log PostgreSQL su uno shard partecipante:

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;

Se si esegue il tracciamento delle query, a ogni riga di log viene aggiunto un identificatore univoco di 31 cifre. Qui, 1126253375719408502700000000011 e 1126253375719408502700000000010 rappresentano gli ID di tracciamento per i nodi coordinatore e partecipante, rispettivamente.

  • Identificatore della transazione: 11262533757194085027

  • Identificatore del comando: 112625337571940850270000000001

  • Identificatore del tipo di nodo: l’ultima cifra, 1 o 0, indica un router coordinatore e un nodo partecipante, rispettivamente.

Correlazione di log per individuare il tempo di esecuzione della query su vari nodi

In questo esempio, il parametro log_min_duration_statement è stato aggiornato a 0 per stampare la durata di tutte le query.

Senza tracciamento delle query
2024-01-15 07:28:46 UTC:[local]:postgres@postgres_limitless:[178322]:LOG: duration: 12.779 ms statement: select * from customers;
Con tracciamento delle query

File di log PostgreSQL sul router coordinatore:

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

File di log PostgreSQL su uno shard partecipante:

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