26.10.2025 09:23
rostov 0 281 Источник

Зачем нужны ID запросов в логах?

Когда вы работаете с распределённой системой — будь то микросервисы, фронтенд + бэкенд или nginx + приложение — жизненно важно иметь возможность «протянуть» один и тот же идентификатор запроса через все её компоненты. Это позволяет сопоставлять логи из разных источников, быстро находить ошибки и проводить корреляционный анализ.

В nginx для этого из коробки есть переменная $request_id — 32-символьный hex-идентификатор (например, a1b2c3d4e5f678901234567890abcdef). Его можно передать бэкенду через proxy_set_header X-Request-ID $request_id; или fastcgi_param HTTP_X_REQUEST_ID $request_id;, а также сохранить в access-логах.

Однако стандартный $request_id — это просто случайная строка без временной привязки и без структуры, удобной для аналитики. В этой статье мы рассмотрим, как улучшить ситуацию с помощью ULID и UUIDv7.

Быстрое решение без модулей: UUIDv4 из $request_id через map

Если вы не хотите собирать nginx с модулями, можно «причесать» $request_id до формата UUIDv4 с помощью директивы map:

map $request_id $request_uuidv4 {
    "~^(.{8})(.{4})(.{4})(.{4})(.{12})$" "$1-$2-$3-$4-$5";
}

Теперь в логах и заголовках вы можете использовать $request_uuidv4 — он будет выглядеть как a1b2c3d4-e5f6-7890-1234-567890abcdef.

Это решение простое и не требует пересборки nginx.

Почему UUIDv4 — не лучший выбор для анализа логов?

UUIDv4 не содержит временной компоненты. При вставке в таблицу ClickHouse такие ID распределяются хаотично. Это означает невозможность эффективного использования MinMax-индексы, что приводит в полному сканированию данных. На больших объемах это может быть больно.

ULID и UUIDv7: сортируемые идентификаторы с временной меткой

ULID и UUIDv7 — это современные альтернативы UUIDv4, разработанные именно для аналитических сценариев:

  • Сортируемость: оба формата естественным образом сортируются по времени создания.

  • Встроенная временная метка: точность до миллисекунд (ULID — 48 бит времени, UUIDv7 — 48 бит Unix-времени в миллисекундах).

  • Уникальность: обеспечивается за счёт случайной или энтропийной части (80 бит у ULID, 74 бита у UUIDv7).

  • Совместимость: UUIDv7 соответствует RFC 9562, ULID — де-факто стандарт с широкой поддержкой.

  • Эффективность в ClickHouse: благодаря временной компоненте предполагается, что MinMax-индексы позволят пропускать нерелевантные блоки данных при поиске по ID.

Это делает ULID и UUIDv7 идеальными кандидатами для использования в логах, особенно если вы храните их в ClickHouse с временной партицией.

Практический эксперимент: генерация ID, загрузка в ClickHouse, замеры

Для генерации ULID, UUIDv4 и UUIDv7 я использовал модуль ngx_http_idgen_module. Модуль:

  • Генерирует ID лениво — только при первом обращении к переменной.

  • Использует стандартный $request_id как источник энтропии (32 hex-символа → 128 бит).

  • Кэширует результат в контексте запроса — нулевые накладные расходы при повторном использовании.

Конфигурация nginx

user nginx;
worker_processes 4;
error_log /var/log/nginx/error.log warn;
pid /var/run/nginx.pid;

events {
    worker_connections 1024;
}

http {
    log_format json escape=json '{'
        '"timestamp": $msec,'
        '"request_id": "$request_id",'
        '"ulid": "$request_ulid",'
        '"uuidv4": "$request_uuidv4",'
        '"uuidv7": "$request_uuidv7"'
    '}';

    access_log syslog:server=127.0.0.1:1514 json;

    server {
        listen 7080;
        location / {
            return 200 'OK';
        }
    }
}

В логах используется $msec это не обязательно, больше привычка.

Важно: время в ULID/UUIDv7 — это момент начала обработки запроса внутри nginx. Оно может отличаться от $msec. Но эта разница не существенно повлияет на хаотичность расположения наших ID.

Схема таблицы в ClickHouse

CREATE TABLE logs.requests
(
    `timestamp` DateTime64(3),
    `request_id` FixedString(32),
    `ulid` FixedString(26),
    `uuidv4` UUID,
    `uuidv7` UUID,
    INDEX idx_ulid ulid TYPE minmax GRANULARITY 4,
    INDEX idx_uuidv7 uuidv7 TYPE minmax GRANULARITY 4
)
ENGINE = MergeTree
PARTITION BY toStartOfHour(timestamp)
ORDER BY timestamp

  • FixedString(26) — оптимальный тип для ULID (26 ASCII-символов).

  • UUID — встроенный тип ClickHouse для UUIDv4 и UUIDv7 (хранится как 16 байт).

  • Партицирование по часу — для удобства эксперимента.

Загрузка логов

Логи в формате JSON загружаются в ClickHouse через Vector:

api:
  enabled: true
  address: "127.0.0.1:8686"

sources:
  source_nginx_udp:
    type: syslog
    address: 0.0.0.0:1514
    max_length: 1024000
    mode: udp

transforms:
  remap_nginx:
    type: remap
    inputs:
      - source_nginx_udp
    reroute_dropped: true
    file: /etc/vector/remap_nginx.vrl

sinks:
  to_click_nginx_access:
    inputs: [ remap_nginx ]
    type: clickhouse
    database: logs
    endpoint: 127.0.0.1:8124
    table: requests
    skip_unknown_fields: true
    healthcheck:
      enabled: false
    encoding:
      timestamp_format: unix_ms
    auth:
      user: vector
      password: vector
      strategy: basic

Файл remap_nginx.vrl

if !is_nullish(.message) {
    json, .fail_parse.message_err = parse_json(.message)
    if .fail_parse.message_err != null {
        .fail_parse.message = del(.message)
    } else {
        . = json
        del(.fail_parse.message_err)
    }
}

if is_float(.timestamp) {
   .timestamp = from_unix_timestamp!(to_int!(.timestamp*1000 ?? 0), unit: "milliseconds") 
} else {
   .fail_parse.timestamp = to_string!(.timestamp)
   .timestamp = now()
}

Осталось запустить генератор запросов, для этого нам подойдет ab из пакета apache2-utils

ab -c 50 http://10.10.10.110:7080/

Через некоторое время получаем некоторое количество данных

SELECT
    column,
    type,
    formatReadableSize(sum(column_data_compressed_bytes)) AS compressed,
    formatReadableSize(sum(column_data_uncompressed_bytes)) AS uncompressed,
    sum(rows) AS rows_cnt,
    round(sum(column_data_uncompressed_bytes) / sum(rows), 2) AS avg_row
FROM system.parts_columns
WHERE (active = 1) AND (database = 'logs') AND (`table` = 'requests')
GROUP BY
    column,
    type
ORDER BY avg_row ASC

   ┌─column─────┬─type────────────┬─compressed─┬─uncompressed─┬─rows_cnt─┬─avg_row─┐
1. │ timestamp  │ DateTime64(3)   │ 35.80 MiB  │ 430.66 MiB   │ 56689348 │    7.97 │
2. │ uuidv7     │ UUID            │ 688.86 MiB │ 861.32 MiB   │ 56689348 │   15.93 │
3. │ uuidv4     │ UUID            │ 864.87 MiB │ 861.32 MiB   │ 56689348 │   15.93 │
4. │ ulid       │ FixedString(26) │ 1.04 GiB   │ 1.37 GiB     │ 56689348 │   25.89 │
5. │ request_id │ FixedString(32) │ 1.69 GiB   │ 1.68 GiB     │ 56689348 │   31.86 │
   └────────────┴─────────────────┴────────────┴──────────────┴──────────┴─────────┘

Сначала посмотрим как происходит выборка по полям request_id и uuidv4

SELECT *
FROM logs.requests
WHERE request_id = '75c0bbe9c789ffa3ad1d0035b395e461'

Row 1:
──────
timestamp:  2025-10-22 15:56:29.281
request_id: 75c0bbe9c789ffa3ad1d0035b395e461
ulid:       01K85ZW2B1EQ0BQTE7H7ZT7B8X
uuidv4:     75c0bbe9-c789-4fa3-ad1d-0035b395e461
uuidv7:     019a0bfe-0961-7fa3-ad1d-0035b395e461

1 row in set. Elapsed: 34.825 sec. Processed 56.69 million rows, 1.81 GB (1.63 million rows/s., 52.09 MB/s.)
Peak memory usage: 3.92 MiB.
SELECT *
FROM logs.requests
WHERE uuidv4 = '75c0bbe9-c789-4fa3-ad1d-0035b395e461'

Row 1:
──────
timestamp:  2025-10-22 15:56:29.281
request_id: 75c0bbe9c789ffa3ad1d0035b395e461
ulid:       01K85ZW2B1EQ0BQTE7H7ZT7B8X
uuidv4:     75c0bbe9-c789-4fa3-ad1d-0035b395e461
uuidv7:     019a0bfe-0961-7fa3-ad1d-0035b395e461

1 row in set. Elapsed: 17.914 sec. Processed 56.69 million rows, 907.03 MB (3.16 million rows/s., 50.63 MB/s.)
Peak memory usage: 1.90 MiB.

В целом, все в пределах ожиданий, сканируются все 56 миллионов строк, у uuidv4 есть небольшое ускорение за счет более оптимального формата хранения.

SELECT *
FROM logs.requests
WHERE ulid = '01K85ZW2B1EQ0BQTE7H7ZT7B8X'

Row 1:
──────
timestamp:  2025-10-22 15:56:29.281
request_id: 75c0bbe9c789ffa3ad1d0035b395e461
ulid:       01K85ZW2B1EQ0BQTE7H7ZT7B8X
uuidv4:     75c0bbe9-c789-4fa3-ad1d-0035b395e461
uuidv7:     019a0bfe-0961-7fa3-ad1d-0035b395e461

1 row in set. Elapsed: 0.205 sec. Processed 32.77 thousand rows, 852.03 KB (159.65 thousand rows/s., 4.15 MB/s.)
Peak memory usage: 11.85 KiB.

Результат впечатляет, но он ожидаем, попробуем по колонке в которой храним UUIDv7 в формате UUID, должно быть эффективнее?

SELECT *
FROM logs.requests
WHERE uuidv7 = '019a0bfe-0961-7fa3-ad1d-0035b395e461'

Row 1:
──────
timestamp:  2025-10-22 15:56:29.281
request_id: 75c0bbe9c789ffa3ad1d0035b395e461
ulid:       01K85ZW2B1EQ0BQTE7H7ZT7B8X
uuidv4:     75c0bbe9-c789-4fa3-ad1d-0035b395e461
uuidv7:     019a0bfe-0961-7fa3-ad1d-0035b395e461

1 row in set. Elapsed: 16.020 sec. Processed 56.69 million rows, 907.03 MB (3.54 million rows/s., 56.62 MB/s.)
Peak memory usage: 1.42 MiB.

Что-то пошло не так, откуда 56 миллионов? Сравним планы запросов

EXPLAIN indexes = 1
SELECT *
FROM logs.requests
WHERE uuidv7 = '019a0bfe-0961-7fa3-ad1d-0035b395e461'

    ┌─explain────────────────────────────────────────────────────────────┐
 1. │ Expression ((Project names + Projection))                          │
 2. │   Expression ((WHERE + Change column names to column identifiers)) │
 3. │     ReadFromMergeTree (logs.requests)                              │
 4. │     Indexes:                                                       │
 5. │       MinMax                                                       │
 6. │         Condition: true                                            │
 7. │         Parts: 19/19                                               │
 8. │         Granules: 6929/6929                                        │
 9. │       Partition                                                    │
10. │         Condition: true                                            │
11. │         Parts: 19/19                                               │
12. │         Granules: 6929/6929                                        │
13. │       PrimaryKey                                                   │
14. │         Condition: true                                            │
15. │         Parts: 19/19                                               │
16. │         Granules: 6929/6929                                        │
17. │       Skip                                                         │
18. │         Name: idx_uuidv7                                           │
19. │         Description: minmax GRANULARITY 4                          │
20. │         Parts: 19/19                                               │
21. │         Granules: 6929/6929                                        │
    └────────────────────────────────────────────────────────────────────┘

EXPLAIN indexes = 1
SELECT *
FROM logs.requests
WHERE ulid = '01K85ZW2B1EQ0BQTE7H7ZT7B8X'

    ┌─explain────────────────────────────────────────────────────────────┐
 1. │ Expression ((Project names + Projection))                          │
 2. │   Expression ((WHERE + Change column names to column identifiers)) │
 3. │     ReadFromMergeTree (logs.requests)                              │
 4. │     Indexes:                                                       │
 5. │       MinMax                                                       │
 6. │         Condition: true                                            │
 7. │         Parts: 19/19                                               │
 8. │         Granules: 6929/6929                                        │
 9. │       Partition                                                    │
10. │         Condition: true                                            │
11. │         Parts: 19/19                                               │
12. │         Granules: 6929/6929                                        │
13. │       PrimaryKey                                                   │
14. │         Condition: true                                            │
15. │         Parts: 19/19                                               │
16. │         Granules: 6929/6929                                        │
17. │       Skip                                                         │
18. │         Name: idx_ulid                                             │
19. │         Description: minmax GRANULARITY 4                          │
20. │         Parts: 1/19                                                │
21. │         Granules: 4/6929                                           │
    └────────────────────────────────────────────────────────────────────┘

Видно, что по какой-то причине для поля ulid обрабатывалось 4/6929 гранул, а для uuidv7 6929/6929

Если заглянуть в документацию, то можно встретить строку:

Due to historical reasons, UUIDs are sorted by their second half.

Для UUIDv7 это означает, что сортировка будет происходить сначала по рандомной части, и так же как для UUIDv4, индекс MinMax перестанет иметь смысл.
Тесты с записью UUIDv7 в String проводить не стал, т.к. статья и так получилась длиннее изначального плана.

Выводы и рекомендации:

  1. Индекс MinMax прекрасно себя показывает на полях начинающихся с временной компоненты и отсортированных по полю которое коррелирует со временем этой компоненты.

  2. Индекс MinMax работает не корректно для UUIDv7 в случае хранения в формате UUID

  3. Если у вас есть необходимость работать именно с UUIDv7, то для ускорения выборки с помощью индекса MinMax, храните в формате FixedString(36) или String



Если вы уже используете Lua в nginx (например, через OpenResty), вы можете реализовать генерацию ULID/UUIDv7 на стороне скрипта. Я буду рад увидеть живые примеры — особенно с замерами производительности и объёмов. Возможно, Lua-решение окажется ещё проще для некоторых сценариев.

Послесловие

Я — автор модуля ngx_http_idgen_module, и эта статья родилась из реальных задач по оптимизации логирования в ClickHouse. Модуль открыт для конструктивной критики, предложений и PR. Если вы видите, как его можно улучшить — пишите!

Комментарии (0)