Гость
Войти | Профиль | Очистить
Действия ...
Форумы / PostgreSQL [игнор отключен] [закрыт для гостей] / ExclusiveLock extend на пустой базе и с ее ростом пропадает / 3 сообщений из 3, страница 1 из 1
03.02.2022, 18:46
    #40131535
serg_777777
serg_777777
Гость
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
ExclusiveLock extend на пустой базе и с ее ростом пропадает
День добрый.

Тестируем некоторое Java приложение и наблюдаем следующее поведение.
Код: sql
1.
2.
3.
4.
5.
6.
RHEL 7.9
виртуалка, 8vCPU/16Gb
PG 11.14 (пробовал и 12.9)
swap off
echo never > /sys/kernel/mm/transparent_hugepage/enabled
echo never > /sys/kernel/mm/transparent_hugepage/defrag



Очищаю тестовую БД (truncate table->vacuum)
shared_buffers = '2096MB'

Подаю нагрузку и через какие-то интервалы получаю ExclusiveLock extend. Ожидаю пока таблица вырастет до ~4Gb и все нормализуется. Жду еще 2 часа и все ок.

Опять очищаю тестовую БД (truncate table->vacuum)
shared_buffers = '128MB'

Подаю нагрузку и все ок.


Перерыл весь гугл.
И тут https://www.sql.ru/forum/904894-2/exclusivelock и эти же обсуждения на других ресурсах.
https://www.postgresql.org/message-id/flat/466D72D2-68EC-4FF4-93B8-43B687E7B705@simply.name]https://www.postgresql.org/message-id/flat/466D72D2-68EC-4FF4-93B8-43B687E7B705@simply.name

Много читал где про патч на 9.6 (хотя мой perf top другой . см ниже.), но у меня же уже 11.14 и на 12.9 тоже пробовал.

Дисковая система, судя по iostat, в норме. latency до 5мс и то редкие. Очередей нет.

Опции на томе LVM как советовал Космодемъянский такие:
ext4 (rw,noatime,nodiratime,nobarrier,data=ordered)

Игрался на таблице с fillfactor (пробовал 10 и 70) - не помогло.

perf top в эти моменты показывает следующее:
Код: sql
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
   6.56%  postgres                    [.] tuplehash_insert
   5.74%  postgres                    [.] slot_deform_tuple
   5.39%  postgres                    [.] ExecInterpExpr
   5.27%  [vdso]                      [.] __vdso_clock_gettime
   4.22%  postgres                    [.] HeapTupleSatisfiesMVCC
   3.34%  libc-2.17.so                [.] get_next_seq
   2.21%  postgres                    [.] AllocSetAlloc
   1.91%  postgres                    [.] hash_search_with_hash_value
   1.71%  postgres                    [.] hash_any
   1.58%  postgres                    [.] ExecEvalScalarArrayOp
   1.53%  postgres                    [.] heap_getnext
   1.48%  libc-2.17.so                [.] __memcpy_ssse3_back
   1.39%  [kernel]                    [k] _raw_spin_unlock_irqrestore
   1.33%  postgres                    [.] nocachegetattr



И это "картина" явно отличается от обсуждаемых в ссылках выше про 9ку.

ExecInterpExpr вроде как участвует при разборе SQL для оптимизатора.

CPU в такие моменты в 100%, естественно выстраивается очередь на CPU.

pgbouncer лишь немного смягчает ситуацию урезая кол-во сессий, но не приyципиально.


Меня ставит в тупик именно такое поведение на фактически пустой БД и с ростом БД нормализация ситуации и самое главное отсутствие понимания причины и ее устранения.

Но если фактически убрать shared_buffer до "нуля" (128Мб) этого нет.



Вообщем если у кого есть мысли - направьте на путь истинный.
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
03.02.2022, 19:47
    #40131547
Maxim Boguk
Maxim Boguk
Участник
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
ExclusiveLock extend на пустой базе и с ее ростом пропадает
serg_777777,

Не помешало бы подробное описание нагрузки...
что именно делается, сколько активных соединений с базой, сколько соединения всего?
Включить log_checkpoints и посмотреть не связанны ли " через какие-то интервалы получаю ExclusiveLock extend." как то со временем окончания checkpoint...
" через какие-то интервалы получаю ExclusiveLock extend." - на какое время этот ExclusiveLock висит?
Точно ли именно в это время дисковая система не задумывается (высокая latency).
fillfactor тут точно не поможет.

Какая дисковая система на хосте? nvme/ssd? механика? какой то cloud storage?

Наиболее вероятное объяснение ситуации - это дисковая система становится раком в конце checkpoint при fsync
и поэтому не получается оперативно добавлять страницы к файлам с данными.

PS: "Дисковая система, судя по iostat, в норме. latency до 5мс и то редкие." - c каким временным разрешением вы эту latency снимаете? Если раз в 1-5 минут то и ExclusiveLock extend вызванные проблемами с IO вы там увидите только если там эта проблема будет 1-5 минут продолжаться.

PPS: я бы сильно уменьшил vm.dirty_bytes и vm.dirty_background_bytes (предположим до 8MB и 1MB как совсем safe values, если поможет можно будет аккуратно поднимать удваивая пока норально дисковая система справляется с fsync)

PPPS: это ГИПОТЕЗЫ а не гарантия что проблема именно там.

--
Maxim Boguk
лучшая поддержка PostgreSQL: dataegret.ru
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
04.02.2022, 11:42
    #40131648
serg_777777
serg_777777
Гость
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
ExclusiveLock extend на пустой базе и с ее ростом пропадает
Maxim Boguk,
спасибо за советы.

Нагрузка тестовая, синтетическая.
~2.5K транзакций/сек (коммитов)
Диски конечно облачные, куда же теперь без этих облаков :) Вообщем неизвестно что там и через какие кэши это все проходит.

Конкурируют Insert-ы и select за одну таблицу вроде бы.

Пока попробовал следующе:
выставил
sudo sysctl vm.dirty_bytes=8388608
sudo sysctl vm.dirty_background_bytes=1048576

shared_buffers = '2096MB'
Очистил БД (truncate table->vacuum)

Проблема повторилась.

Что касается статистики IO - собираю часто, 1 раз в секунду через /proc....
Вот привожу пример через iostat

Видим начало проблемы в vmstat в 11:05:27:
Видим дикую очередь процессов (первый столбец и ~100% утилизацию CPU)

Код: java
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- -----timestamp-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st                 MSK
 7  1      0 4657076  33924 5962620    0    0     0 33468 75747 23501 51  9 37  3  0 2022-02-04 11:05:16
 6  0      0 4645740  33924 5973564    0    0     0 33024 77162 25113 37  8 51  3  0 2022-02-04 11:05:17
 8  0      0 4629492  33932 5985912    0    0     0 33468 78668 26283 32  8 57  3  0 2022-02-04 11:05:18
 5  1      0 4612892  33932 5996964    0    0     0 34160 79945 26756 32  8 56  4  0 2022-02-04 11:05:19
 9  0      0 4594892  33932 6007308    0    0     0 32208 79373 26640 32  7 57  4  0 2022-02-04 11:05:20
 0  0      0 4574860  33952 6018336    0    0     0 33272 77824 25960 31  7 58  4  0 2022-02-04 11:05:21
19  0      0 4559568  33952 6029812    0    0     0 33472 79238 26248 35  8 53  4  0 2022-02-04 11:05:22
 4  1      0 4543100  33960 6041884    0    0     0 33880 78733 26194 33  8 55  4  0 2022-02-04 11:05:23
19  1      0 4528008  33960 6051976    0    0     0 31560 77886 25720 32  8 56  3  0 2022-02-04 11:05:24
 7  0      0 4463660  33960 6062248    0    0     0 31604 76042 23937 37  8 51  3  0 2022-02-04 11:05:25
15  2      0 4437692  33976 6072540    0    0     0 30888 74440 23513 43  8 47  3  0 2022-02-04 11:05:26
87  1      0 4180616  33976 6081436    0    0     0 23468 67858 19549 65 10 23  2  0 2022-02-04 11:05:27
139  2      0 3725588  33976 6088460    0    0     0 17412 59115 12455 85 15  0  0  0 2022-02-04 11:05:28
199  0      0 3510272  33984 6094420    0    0     0 14876 64538 12077 87 13  0  0  0 2022-02-04 11:05:29
135  0      0 3936920  33984 6101428    0    0     0 17632 69199 13589 86 14  0  0  0 2022-02-04 11:05:30
138  0      0 3834260  34000 6106856    0    0     0 12728 59761 10709 90 10  0  0  0 2022-02-04 11:05:31
198  1      0 3160476  34000 6112936    0    0     0 16144 65052 13865 88 12  0  0  0 2022-02-04 11:05:32




Вот вывод iostat (извиняюсь за длинный листинг):
WAL лежат на sdb, datafiles на sdc
Вроде как все красиво. Я бы сказал, что нагрузка на IO наоборот упала.
Код: java
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.
73.
74.
75.
76.
77.
78.
79.
80.
81.
82.
83.
84.
85.
86.
87.
88.
89.
02/04/2022 11:05:16 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00    74.00    0.00  957.00     0.00 20944.00    43.77     0.47    0.49    0.00    0.49   0.48  45.80
sdc               0.00   115.00    0.00  174.00     0.00 12584.00   144.64     0.21    1.20    0.00    1.20   0.26   4.50

02/04/2022 11:05:17 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00  997.00     0.00 21424.00    42.98     0.44    0.44    0.00    0.44   0.43  43.30
sda               0.00     7.00    0.00    4.00     0.00    44.00    22.00     0.00    0.25    0.00    0.25   0.25   0.10
sdc               0.00     2.00    0.00  111.00     0.00 10520.00   189.55     0.19    1.73    0.00    1.73   0.20   2.20

02/04/2022 11:05:18 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00 1110.00     0.00 22360.00    40.29     0.44    0.39    0.00    0.39   0.39  43.30
sdc               0.00    10.00    0.00  139.00     0.00 10832.00   155.86     0.31    2.22    0.00    2.22   0.22   3.10

02/04/2022 11:05:19 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00 1082.00     0.00 22232.00    41.09     0.46    0.43    0.00    0.43   0.43  46.40
sdc               0.00     1.00    0.00   96.00     0.00 11912.00   248.17     0.20    2.14    0.00    2.14   0.25   2.40

02/04/2022 11:05:20 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00 1019.00     0.00 21980.00    43.14     0.49    0.49    0.00    0.49   0.48  49.20
sda               0.00     2.00    0.00    7.00     0.00    36.00    10.29     0.00    0.00    0.00    0.00   0.00   0.00
sdc               0.00     1.00    0.00  112.00     0.00 11448.00   204.43     0.18    1.64    0.00    1.64   0.21   2.40

02/04/2022 11:05:21 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00    32.00    0.00 1048.00     0.00 22004.00    41.99     0.46    0.44    0.00    0.44   0.43  45.40
sdc               0.00    85.00    0.00  114.00     0.00 10108.00   177.33     0.25    2.19    0.00    2.19   0.25   2.80

02/04/2022 11:05:22 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00  963.00     0.00 22384.00    46.49     0.54    0.56    0.00    0.56   0.56  54.00
sdc               0.00     1.00    0.00  105.00     0.00 11056.00   210.59     0.19    1.87    0.00    1.87   0.26   2.70

02/04/2022 11:05:23 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00 1043.00     0.00 22624.00    43.38     0.48    0.47    0.00    0.47   0.46  48.00
sda               0.00     2.00    0.00    2.00     0.00    16.00    16.00     0.00    0.50    0.00    0.50   0.50   0.10
sdc               0.00     1.00    0.00  102.00     0.00 11360.00   222.75     0.17    1.72    0.00    1.72   0.22   2.20

02/04/2022 11:05:24 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00 1075.00     0.00 22536.00    41.93     0.40    0.37    0.00    0.37   0.37  39.70
sdc               0.00     0.00    0.00  102.00     0.00 10520.00   206.27     0.16    1.59    0.00    1.59   0.23   2.30

02/04/2022 11:05:25 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00  913.00     0.00 20624.00    45.18     0.44    0.48    0.00    0.48   0.48  43.50
sdc               0.00     2.00    0.00  175.00     0.00 10184.00   116.39     0.20    1.18    0.00    1.18   0.14   2.50

02/04/2022 11:05:26 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     6.00    0.00  949.00     0.00 20672.00    43.57     0.39    0.41    0.00    0.41   0.41  39.00
sdc               0.00    40.00    0.00   91.00     0.00  9380.00   206.15     0.10    1.12    0.00    1.12   0.19   1.70

02/04/2022 11:05:27 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     3.00    0.00  676.00     0.00 16604.00    49.12     0.32    0.48    0.00    0.48   0.47  31.50
sdc               0.00     2.00    0.00   63.00     0.00  6800.00   215.87     0.17    2.76    0.00    2.76   0.30   1.90

02/04/2022 11:05:28 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00  247.00     0.00  9876.00    79.97     0.12    0.50    0.00    0.50   0.47  11.60
sda               0.00     2.00    0.00    2.00     0.00    16.00    16.00     0.00    0.50    0.00    0.50   0.50   0.10
sdc               0.00     1.00    0.00   56.00     0.00  7032.00   251.14     0.10    1.80    0.00    1.80   0.30   1.70

02/04/2022 11:05:29 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00  196.00     0.00 10036.00   102.41     0.10    0.53    0.00    0.53   0.48   9.50
sdc               0.00     1.00    0.00   95.00     0.00  4712.00    99.20     0.33    3.46    0.00    3.46   0.18   1.70

02/04/2022 11:05:30 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00  281.00     0.00 10860.00    77.30     0.14    0.49    0.00    0.49   0.47  13.30
sda               0.00     0.00    0.00    3.00     0.00    20.00    13.33     0.00    0.00    0.00    0.00   0.00   0.00
sdc               0.00     1.00    0.00  175.00     0.00  6792.00    77.62     0.23    1.31    0.00    1.31   0.12   2.10

02/04/2022 11:05:31 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00    17.00    0.00  243.00     0.00  8000.00    65.84     0.12    0.49    0.00    0.49   0.43  10.50
sdc               0.00    30.00    0.00   32.00     0.00  4808.00   300.50     0.09    2.75    0.00    2.75   0.31   1.00

02/04/2022 11:05:32 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sdb               0.00     0.00    0.00  259.41     0.00 11196.04    86.32     0.12    0.45    0.00    0.45   0.42  10.99
sdc               0.00     9.90    0.00  222.77     0.00  4954.46    44.48     0.35    1.57    0.00    1.57   0.05   1.19
...
Рейтинг: 0 / 0
| Ответить | Цитировать | Написать  
Форумы / PostgreSQL [игнор отключен] [закрыт для гостей] / ExclusiveLock extend на пустой базе и с ее ростом пропадает / 3 сообщений из 3, страница 1 из 1
Целевая тема:
Создать новую тему:
Автор:
Найденые пользователи ...
Разблокировать пользователей ...
Читали тему (0):
Читали форум (0):
Пользователи онлайн (0):
Польз. соглашение
созд. / загр.: 135ms
Закрыть
start [/forum/topic.php?fid=53&mobile=1&tid=1993671]:
 0ms
get settings:
 10ms
get forum list:
 12ms
check forum access:
 4ms
check topic access:
 4ms
track hit:
 29ms
get topic data:
 12ms
get forum data:
 3ms
get page messages:
 44ms
get tp. blocked users:
 2ms
others: 15ms
total:  135ms
x
x
Закрыть


Просмотр
0 / 0
Close
Debug Console [Select Text]