|
|
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Доброй ночи. База на postgres 9.2, сейчас 461G, партицирование, при чём не по времени, так что БОЛЬШИХ таблиц сотни и изрядная часть из них дописывается всё время. Периодически (раньше раз в пару месяцев гдето) слетали индексы. реиндекс с вакуумом решали проблему. Последний раз работало без реиндекса больше полгода, но вчера загрузка дисков 100%, вобщем как раньше, когда индекс слетал. Остановил всё что с базой работало, запустил REINDEX DATABASE, и вот, он уже больше 6 часов пашет. есть загрузка в районе 50% и по CPU и по винтам. места в разделе полно (17% занято), рейд 5. Дефрагментация (e4defrag) не предлагалась. Ubuntu Linux 12.04, сервер естественно. какую ещё нужно инфу - спрашивайте. Вобщем, раньше, максимум было 3.5 часа вместе с вакуумом. А тут один реиндекс бесконечный. Чтото не то. Предложите что ни будь, пожалуйста. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 11.09.2014, 04:36:30 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, какое значение стоит в maintenance_work_mem и сколько установлено памяти? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 11.09.2014, 09:24:23 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel как раньше, когда индекс слетал Если в вашей базе повреждается индекс, что-то не в порядке с железом. В любом случае, это не повод для reindex database. Вы можете сделать reindex конкретного индекса, или создать новый, а потом удалить старый. Как правило, это много быстрее. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 11.09.2014, 10:25:36 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Всех прошу прощения за беспокойство. реиндекс завершился через 11 часов. База работает. То что с периодическим падением индексов надо чтото делать - отдельный вопрос. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 11.09.2014, 10:59:56 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Alexiusкакое значение стоит в maintenance_work_mem и сколько установлено памяти? Памяти 16G shared_buffers = 2GB work_mem = 64MB maintenance_work_mem = 2GB ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 11.09.2014, 21:00:45 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Что бы не заводить новую тему спрошу здесь же, т.к. всё про эту же базу (пока база ещё работает). Дело в том, что основные (большие) таблицы базы только заполняются (INSERT), ну и просматриваются конечно. Но UPDATE и DELETE на них не делается никогда. Таблицы хранят данные мониторинга, каждые по своему объекту (заполняются параллельно). Через некоторое время (месяцы) ненужные таблицы пользователи удаляют (для них они объекты мониторинга). И создание таблиц (с индексами, конечно) и удаление, через хранимки. Так вот, какие профилактические действия стОит делать с такой базой? Имеет ли в таком случае регулярный VACUUM FULL ANALYZE / CLUSTER ? Или достаточно просто ANALYZE ? В базе иногда слетают индексы (см. стартовое сообщение темы), это лечится REINDEX DATABASE. Отчего (кроме бедблоков) такое может быть? Как лечить. А то, с ростом базы (460Г) время REINDEX-а становится уже очень большим. Может можно найти какой именно индекс слетел, чтобы быстрее восстановится. Проблема усугубляется тем, что пользователи имеют доступ к серверу, и если он "виснет" (или им кажется что виснет), первым делом нажимают reset на сервере. Я им говорил что этого делать нельзя N раз, бесполезно, так что примем как данное. Предположить что индексы слетают ТОЛЬКО от их ресетов я тоже не могу. Система может работать два месяца без перезагрузок, потом, по непонятной причине, загрузка дисков (sar -d) быстро нарастает до 100%, пользователи делают свои ресеты несколько раз, потом связываются со мной. Я останавливаю приложения работающие с базой, запускаю реиндекс, потом вакуум и этого на какое то время хватает. Что в такой ситуации посоветуете? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 14.09.2014, 13:07:39 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, партиционируйте таблицы (по времени). сломайте кнопку ресет на сервере. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 14.09.2014, 13:53:41 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, Что у Вас с настройками: - autovacuum (подозреваю, что off) - autovacuum_max_workers (подозреваю, что по умолчанию 3) Какой поток был в top, когда наблюдалась повышенная загрузка дисков. Подозреваю, что это был wraparound autovacuum Судя по вопросам, vacuum в ручном режиме не выполнялся. Предполагаю, что у Вас периодически запускался принудительный VACUUM всей базы для предотвращения wraparound транзакций. Из-за этого была экстремально высокая нагрузка к дискам. Поэтому пользователи не могли добраться до своих данных за разумное время. Если мое предположение верно, то Вас следует настроить либо автовакуум, либо ручной вакуум в период обслуживания. Переиндексация не требуется. Если будете настраивать автовакуум, то нужно увеличить число worker автовакуума. Так же можно поднастроить на существенно более агрессивные значения параметров работы автовакуума. Если будете делать ручной вакуум таблиц, то можете не уложиться в окно для технического обслуживания (то есть время работы ручного вакуума порядка нескольких суток). ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 14.09.2014, 14:57:09 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
/\/\/\/\/\/\/\- autovacuum (подозреваю, что off) - autovacuum_max_workers (подозреваю, что по умолчанию 3) autovacuum = on , все настройки вакуума по дефолту, да. /\/\/\/\/\/\/\Какой поток был в top, когда наблюдалась повышенная загрузка дисков. Подозреваю, что это был wraparound autovacuum Грешен. не смотрел. /\/\/\/\/\/\/\Судя по вопросам, vacuum в ручном режиме не выполнялся. Раньше делал VACUUM FULL ANALYZE и CLUSTER. Ещё бы понять в какой последовательности их делать. (Или не делать). Что это такое в документации, и тут на форуме, читал. Но, полагал, что раз UPDATE ... DELETE нет, то часто делать и не надо. Насколько понимаю, я не прав. /\/\/\/\/\/\/\Если будете настраивать автовакуум, то нужно увеличить число worker автовакуума. Так же можно поднастроить на существенно более агрессивные значения параметров работы автовакуума. Из каких критериев эти параметры выбирать? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 14.09.2014, 15:32:58 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel/\/\/\/\/\/\/\- autovacuum (подозреваю, что off) - autovacuum_max_workers (подозреваю, что по умолчанию 3) autovacuum = on , все настройки вакуума по дефолту, да. AUTOVACUUM можно настраивать для каждой таблицы отдельно. Просмотрите, если он выключен хотя бы для одной, то счетчик транзакций не сбрасывается - именно той таблицей и может держаться. Для таблицы есть опция: WITH ( storage_parameter [= value] [, ... ] ). А в ней параметр: autovacuum_enabled, toast.autovacuum_enabled. Почитайте внимательно. Гадость в том, что через pgAdmin эту опцию посмотреть затруднительно. Лучше смотреть консольным клиентом. AltCtrlDelЧто это такое в документации, и тут на форуме, читал. Но, полагал, что раз UPDATE ... DELETE нет, то часто делать и не надо. Насколько понимаю, я не прав. Наверняка сказать не могу, но посмотрите пункт 4, и в какой момент он у Вас выполняется. AltCtrlDel/\/\/\/\/\/\/\Если будете настраивать автовакуум, то нужно увеличить число worker автовакуума. Так же можно поднастроить на существенно более агрессивные значения параметров работы автовакуума. Из каких критериев эти параметры выбирать? Методом научного тыка. Максим Богук приводил эти параметры на форуме несколько раз (например, здесь: 16288463 ). Можно поиграть параметрами из раздела 18.4.4. Эти параметры можно настроить для каждой таблицы отдельно. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 14.09.2014, 17:37:17 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
/\/\/\/\/\/\/\AUTOVACUUM можно настраивать для каждой таблицы отдельно. Просмотрите, если он выключен хотя бы для одной Там, из больших, две партицированные таблицы, у каждой по 100+ партиций. Они все одинаковые, естественно, параметры autovacuum_* не используются. /\/\/\/\/\/\/\Наверняка сказать не могу, но посмотрите пункт 4, и в какой момент он у Вас выполняется. Тут, вот, я не понял, про какой 4-ый пункт Вы говорите. В остальном, спасибо за подробное объяснение. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 14.09.2014, 18:45:13 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel..., естественно, ... На этом погорело очень много людей. Для меня фраза является детектором необходимости тщательной проверки. авторPostgreSQL's VACUUM command has to process each table on a regular basis for several reasons: 1. To recover or reuse disk space occupied by updated or deleted rows. 2. To update data statistics used by the PostgreSQL query planner. 3. To update the visibility map, which speeds up index-only scans. 4. To protect against loss of very old data due to transaction ID wraparound. Это из документации , параграф 23.1.1. Там же ниже указаны запросы для анализа frozenid. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 14.09.2014, 19:09:17 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
/\/\/\/\/\/\/\Какой поток был в top, когда наблюдалась повышенная загрузка дисков. Подозреваю, что это был wraparound autovacuum "Зависло" снова. Загрузка винтов под 100%, сервер не перезагружали - обратились ко мне. Грузил не автовакуум, а рабочие процессы постгреса и апач (там веб-приложение). по SELECT ... FROM pg_stat_activity видна туча повисших SELECT-ов. Туча, как я понимаю от приложения. Запросы были чаще чем время на ответ. Остановил всё что с базой работает. Перезапустил постгрес. Запустил всё что с базой работает. Очень быстро (минуты) начались тормоза опять. Остановил апач и пр., запустил VACUUM FULL ANALYZE, он работал 5 часов. Я не дождался, перезапустил постгрес, запустил скрипт Код: plsql 1. 2. 3. REINDEX выполнялся 5 часов. Остальное 3 часа. Сейчас система работает. Не знаю что делать. Кстати, пробовал ранее Код: html 1. 2. 3. 4. 5. 6. 7. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 18.09.2014, 11:27:16 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel/\/\/\/\/\/\/\Какой поток был в top, когда наблюдалась повышенная загрузка дисков. Подозреваю, что это был wraparound autovacuum "Зависло" снова. Загрузка винтов под 100%, сервер не перезагружали - обратились ко мне. Грузил не автовакуум, а рабочие процессы постгреса и апач (там веб-приложение). по SELECT ... FROM pg_stat_activity видна туча повисших SELECT-ов. Туча, как я понимаю от приложения. Запросы были чаще чем время на ответ. Остановил всё что с базой работает. Перезапустил постгрес. Запустил всё что с базой работает. Очень быстро (минуты) начались тормоза опять. Остановил апач и пр., запустил VACUUM FULL ANALYZE, он работал 5 часов. Я не дождался, перезапустил постгрес, запустил скрипт Код: plsql 1. 2. 3. REINDEX выполнялся 5 часов. Остальное 3 часа. Сейчас система работает. Не знаю что делать. Кстати, пробовал ранее Код: html 1. 2. 3. 4. 5. 6. 7. вполне возможно что у вас база уже доросла до размера при котором имеющийся сервер просто не справляется... vacuum full/reindex позволяет получить те самые 10-20% которых не хватает... дальше будет хуже вполне возможно. 1)какой у вас размер базы 2)сколько памяти на сервере и сколько выделено shared buffers 3)живет ли еще что то на сервере кроме базы 4)какая дисковая подсистема (сколько дисков в рейде, какие, какой рейд контроллер, есть ли кеш с батарейкой на борту контроллера)? Про autovacuum надо дать ему отработать 1 раз до конца потом он будет сильно меньше грузить... попробуйте или запустить его в ночное время или поднять autovacuum_vacuum_cost_delay до 10ms и уменьшить autovacuum_max_workers до 4рех например. --Maxim Boguk www.postgresql-consulting.ru ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 18.09.2014, 11:49:39 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Maxim Bogukкакой у вас размер базы 461Г Maxim Bogukсколько памяти на сервере и сколько выделено shared buffers Real memory 15.65 GB total, 2.54 GB used Virtual memory 7.45 GB total, 39.05 MB used shared_buffers = 2GB Maxim Bogukживет ли еще что то на сервере кроме базы Приложение которое пишет в базу через постгресовские команды COPY, восновном, оно практически ничего не грузит - 0.1%. Apache httpd c специальным модом апача в котором реализована серверная часть системы. Апач сейчас 20% CPU грузит. Сервер под одну задачу (цель) выделен. Maxim Bogukкакая дисковая подсистема (сколько дисков в рейде, какие, какой рейд контроллер, есть ли кеш с батарейкой на борту контроллера)? ext4. Сервер SRV-Legion 1U 2xXeon® 5500/5600\12xDDR3 ECC REG (192Gb/1333)\VGA Matrox 8Mb\Onboard Intel SW RAID 0, 1, 10\2*PCI-E 8X\4xUSB\2xGigabit Ethernet (Intel 82576)\до 4 HDD c горячей заменой\Рельсы\PSU 2x650W c резервированием\IPMI+IPKVM 1 шт Intel Xeon E5620 (2.4GHz // QPI 5.86 GT/s // DDR3 1066MHz, cache 12MB, Quad, TB, HT, 80W) 2 шт Жесткий диск 2TB SATA II 7200RPM Enterprise 4 шт Контроллер LSI 9240 4i (2MB, 4xSAS/SATA channels, RAID0, 1, 10, 5 no BBU support) 1 шт Модуль памяти 4GB ECC 1333 DDR3 Reg 8 шт Maxim BogukПро autovacuum надо дать ему отработать 1 раз до конца потом он будет сильно меньше грузить... попробуйте или запустить его в ночное время или поднять autovacuum_vacuum_cost_delay до 10ms и уменьшить autovacuum_max_workers до 4рех например. Система подразумевает работу почти в режиме 24/365. Что ночью, что днём - без разницы. Попробую настроить так. Не понял такой момент. Если только что выполнился VACUUM FULL, то что же делать вначале автовакууму, раз он сразу грузить начинает? Что истощаются ресурсы сервера? Ну, незнаю. Слишком резко загрузка подскакивает. Обычно 2-4 % загрузка дисков, и потом, сразу 95%. Поскольку происходит уже два раза в сутки, посоветуйте что посмотреть во время такой ситуации. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 18.09.2014, 18:44:25 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDelMaxim Bogukкакой у вас размер базы 461Г Maxim Bogukсколько памяти на сервере и сколько выделено shared buffers Real memory 15.65 GB total, 2.54 GB used Virtual memory 7.45 GB total, 39.05 MB used shared_buffers = 2GB Maxim Bogukживет ли еще что то на сервере кроме базы Приложение которое пишет в базу через постгресовские команды COPY, восновном, оно практически ничего не грузит - 0.1%. Apache httpd c специальным модом апача в котором реализована серверная часть системы. Апач сейчас 20% CPU грузит. Сервер под одну задачу (цель) выделен. Maxim Bogukкакая дисковая подсистема (сколько дисков в рейде, какие, какой рейд контроллер, есть ли кеш с батарейкой на борту контроллера)? ext4. Сервер SRV-Legion 1U 2xXeon® 5500/5600\12xDDR3 ECC REG (192Gb/1333)\VGA Matrox 8Mb\Onboard Intel SW RAID 0, 1, 10\2*PCI-E 8X\4xUSB\2xGigabit Ethernet (Intel 82576)\до 4 HDD c горячей заменой\Рельсы\PSU 2x650W c резервированием\IPMI+IPKVM 1 шт Intel Xeon E5620 (2.4GHz // QPI 5.86 GT/s // DDR3 1066MHz, cache 12MB, Quad, TB, HT, 80W) 2 шт Жесткий диск 2TB SATA II 7200RPM Enterprise 4 шт Контроллер LSI 9240 4i (2MB, 4xSAS/SATA channels, RAID0, 1, 10, 5 no BBU support) 1 шт Модуль памяти 4GB ECC 1333 DDR3 Reg 8 шт Maxim BogukПро autovacuum надо дать ему отработать 1 раз до конца потом он будет сильно меньше грузить... попробуйте или запустить его в ночное время или поднять autovacuum_vacuum_cost_delay до 10ms и уменьшить autovacuum_max_workers до 4рех например. Система подразумевает работу почти в режиме 24/365. Что ночью, что днём - без разницы. Попробую настроить так. Не понял такой момент. Если только что выполнился VACUUM FULL, то что же делать вначале автовакууму, раз он сразу грузить начинает? Что истощаются ресурсы сервера? Ну, незнаю. Слишком резко загрузка подскакивает. Обычно 2-4 % загрузка дисков, и потом, сразу 95%. Поскольку происходит уже два раза в сутки, посоветуйте что посмотреть во время такой ситуации. 1) log_checkpoints on; и смотреть не совпадают ли пики с окончанием checkpoints (как они у вас кстати настроены)? 2)такой размер базы на таких дисках и рейде жить не будет если в него пишут более менее активно... вам и памяти 64 хотябы надо и дисков штук 8 SAS 15000RPM на нормальной рейд контроллере с батарейкой (в общем нормальный сервер под базу а не low end для веба... нормальые рейды и SAS диски придумали не для того чтобы денег больше снимать а потому что это другой уровень производительности) ну или 2-4 intel s3700 SSD 800GB в рейд тоже поможет даже лучше чем SAS диски (по IOPS будет на 3-4 порядка больше чем ваша текущая дисковая система). 3)во время проблемы cat /proc/meminfo и смотреть что там в районе Dirty: 18372 kB Writeback: 0 kB (и лучше несколько раз посмотреть) 4)iostat -x -m 1 во время проблемы отсчетов 10-20 5)вывод SELECT (now() - pg_stat_activity.xact_start) AS age, pg_stat_activity.datname, pg_stat_activity.procpid, pg_stat_activity.usename, pg_stat_activity.waiting, pg_stat_activity.query_start, pg_stat_activity.client_addr, pg_stat_activity.client_port, pg_stat_activity.current_query FROM pg_stat_activity WHERE ((pg_stat_activity.xact_start IS NOT NULL) AND ((now() - pg_stat_activity.xact_start) > '00:00:10'::interval)) and pg_stat_activity.procpid<>pg_backend_pid() ORDER BY pg_stat_activity.xact_start; во время проблемыюююю особенно интересны первые 5 строк. после этого можно будет думать. Варианты: 1)antiwraparound autovacuum включается или 2)fsync в конце checkpoint диски перегружает или 3)просто сервер не тянет и его каким то запросом или парой убивают --Maxim Boguk www.postgresql-consulting.ru ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 18.09.2014, 19:05:54 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Maxim Boguk1) log_checkpoints on; и смотреть не совпадают ли пики с окончанием checkpoints (как они у вас кстати настроены)? checkpoint_segments = 8 остальное дефолтом Включил логирование, но что там смотреть? :( Проблема начиналась с 16:55 2014-09-20 15:35:26 SAMT ???????: checkpoint complete: wrote 777 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=77.527 s, sync=0.333 s, total=77.917 s; sync files=91, longest=0.048 s, average=0.003 s 2014-09-20 15:39:08 SAMT ???????: checkpoint starting: time 2014-09-20 15:41:38 SAMT ???????: checkpoint complete: wrote 1566 buffers (0.6%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=149.173 s, sync=0.159 s, total=149.351 s; sync files=95, longest=0.030 s, average=0.001 s 2014-09-20 15:44:08 SAMT ???????: checkpoint starting: time 2014-09-20 15:45:26 SAMT ???????: checkpoint complete: wrote 779 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=77.884 s, sync=0.200 s, total=78.104 s; sync files=94, longest=0.053 s, average=0.002 s 2014-09-20 15:49:08 SAMT ???????: checkpoint starting: time 2014-09-20 15:50:08 SAMT ???????: checkpoint complete: wrote 598 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=59.639 s, sync=0.094 s, total=59.801 s; sync files=96, longest=0.014 s, average=0.000 s 2014-09-20 15:54:08 SAMT ???????: checkpoint starting: time 2014-09-20 15:55:07 SAMT ???????: checkpoint complete: wrote 592 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=59.127 s, sync=0.174 s, total=59.307 s; sync files=94, longest=0.042 s, average=0.001 s 2014-09-20 15:59:08 SAMT ???????: checkpoint starting: time 2014-09-20 16:00:31 SAMT ???????: checkpoint complete: wrote 822 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=82.120 s, sync=0.189 s, total=82.394 s; sync files=90, longest=0.052 s, average=0.002 s 2014-09-20 16:04:08 SAMT ???????: checkpoint starting: time 2014-09-20 16:05:00 SAMT ???????: checkpoint complete: wrote 517 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=51.811 s, sync=0.197 s, total=52.032 s; sync files=84, longest=0.021 s, average=0.002 s 2014-09-20 16:09:08 SAMT ???????: checkpoint starting: time 2014-09-20 16:10:02 SAMT ???????: checkpoint complete: wrote 540 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=53.950 s, sync=0.127 s, total=54.082 s; sync files=84, longest=0.027 s, average=0.001 s 2014-09-20 16:14:08 SAMT ???????: checkpoint starting: time 2014-09-20 16:15:02 SAMT ???????: checkpoint complete: wrote 534 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=53.283 s, sync=0.213 s, total=53.526 s; sync files=82, longest=0.041 s, average=0.002 s 2014-09-20 16:19:08 SAMT ???????: checkpoint starting: time 2014-09-20 16:20:03 SAMT ???????: checkpoint complete: wrote 554 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=55.448 s, sync=0.231 s, total=55.748 s; sync files=86, longest=0.037 s, average=0.002 s 2014-09-20 16:24:09 SAMT ???????: checkpoint starting: time 2014-09-20 16:25:04 SAMT ???????: checkpoint complete: wrote 551 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=55.106 s, sync=0.422 s, total=55.591 s; sync files=85, longest=0.049 s, average=0.004 s 2014-09-20 16:29:09 SAMT ???????: checkpoint starting: time 2014-09-20 16:30:05 SAMT ???????: checkpoint complete: wrote 556 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=55.469 s, sync=0.186 s, total=55.686 s; sync files=80, longest=0.031 s, average=0.002 s 2014-09-20 16:34:09 SAMT ???????: checkpoint starting: time 2014-09-20 16:35:03 SAMT ???????: checkpoint complete: wrote 538 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=53.849 s, sync=0.123 s, total=53.998 s; sync files=85, longest=0.023 s, average=0.001 s 2014-09-20 16:39:09 SAMT ???????: checkpoint starting: time 2014-09-20 16:40:05 SAMT ???????: checkpoint complete: wrote 557 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=55.585 s, sync=0.256 s, total=55.898 s; sync files=88, longest=0.030 s, average=0.002 s 2014-09-20 16:44:09 SAMT ???????: checkpoint starting: time 2014-09-20 16:45:03 SAMT ???????: checkpoint complete: wrote 541 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=53.931 s, sync=0.398 s, total=54.369 s; sync files=93, longest=0.142 s, average=0.004 s 2014-09-20 16:49:10 SAMT ???????: checkpoint starting: time 2014-09-20 16:51:41 SAMT ???????: checkpoint complete: wrote 2625 buffers (1.0%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=149.892 s, sync=0.979 s, total=150.965 s; sync files=105, longest=0.241 s, average=0.009 s 2014-09-20 16:54:10 SAMT ???????: checkpoint starting: time 2014-09-20 16:55:08 SAMT ???????: checkpoint complete: wrote 577 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=57.724 s, sync=0.262 s, total=58.041 s; sync files=97, longest=0.058 s, average=0.002 s 2014-09-20 16:59:10 SAMT ???????: checkpoint starting: time 2014-09-20 17:00:42 SAMT ???????: checkpoint complete: wrote 914 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=91.479 s, sync=0.289 s, total=91.774 s; sync files=99, longest=0.042 s, average=0.002 s 2014-09-20 17:04:10 SAMT ???????: checkpoint starting: time 2014-09-20 17:05:16 SAMT ???????: checkpoint complete: wrote 661 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=66.234 s, sync=0.283 s, total=66.598 s; sync files=94, longest=0.053 s, average=0.003 s 2014-09-20 17:09:10 SAMT ???????: checkpoint starting: time 2014-09-20 17:09:48 SAMT ???????: checkpoint complete: wrote 367 buffers (0.1%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=36.735 s, sync=0.464 s, total=37.217 s; sync files=84, longest=0.107 s, average=0.005 s 2014-09-20 17:14:10 SAMT ???????: checkpoint starting: time 2014-09-20 17:14:56 SAMT ???????: checkpoint complete: wrote 457 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=46.197 s, sync=0.412 s, total=46.642 s; sync files=82, longest=0.071 s, average=0.005 s 2014-09-20 17:19:10 SAMT ???????: checkpoint starting: time 2014-09-20 17:20:12 SAMT ???????: checkpoint complete: wrote 613 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=61.261 s, sync=0.441 s, total=61.718 s; sync files=90, longest=0.074 s, average=0.004 s 2014-09-20 17:24:10 SAMT ???????: checkpoint starting: time 2014-09-20 17:24:55 SAMT ???????: checkpoint complete: wrote 442 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=44.154 s, sync=0.341 s, total=44.572 s; sync files=84, longest=0.091 s, average=0.004 s 2014-09-20 17:29:10 SAMT ???????: checkpoint starting: time 2014-09-20 17:30:41 SAMT ???????: checkpoint complete: wrote 897 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=90.633 s, sync=0.380 s, total=91.051 s; sync files=96, longest=0.053 s, average=0.003 s 2014-09-20 17:34:10 SAMT ???????: checkpoint starting: time 2014-09-20 17:35:06 SAMT ???????: checkpoint complete: wrote 560 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=56.186 s, sync=0.260 s, total=56.514 s; sync files=92, longest=0.032 s, average=0.002 s Maxim Boguk3)во время проблемы cat /proc/meminfo и смотреть что там в районе Dirty: 18372 kB Writeback: 0 kB (и лучше несколько раз посмотреть) Dirty: 960 kB Writeback: 0 kB Dirty: 584 kB Writeback: 0 kB Dirty: 804 kB Writeback: 48 kB А вот, кстати, несколько строк по sar -d 00:00:01 DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util 15:35:01 dev8-0 11.18 1.28 319.20 28.66 0.10 8.81 2.65 2.96 15:45:01 dev8-0 7.16 1.25 216.45 30.40 0.09 11.90 3.61 2.58 15:55:01 dev8-0 7.75 7.59 194.04 26.01 0.09 11.29 3.47 2.69 16:05:01 dev8-0 7.24 0.01 187.58 25.90 0.07 9.69 3.27 2.37 16:15:01 dev8-0 6.21 0.43 160.10 25.86 0.07 11.75 3.76 2.33 16:25:01 dev8-0 7.89 4.70 551.06 70.47 0.44 55.30 3.93 3.10 16:35:01 dev8-0 6.95 0.43 174.61 25.17 0.07 10.68 3.70 2.57 16:45:01 dev8-0 8.54 1.49 201.04 23.71 0.06 7.55 2.67 2.28 16:55:01 dev8-0 38.40 903.96 314.22 31.72 0.59 15.29 1.06 4.06 17:05:01 dev8-0 25.93 300.74 190.52 18.95 0.12 4.56 1.58 4.10 17:15:01 dev8-0 1502.55 23934.45 192.22 16.06 1.30 0.87 0.63 95.18 17:25:01 dev8-0 1522.94 24259.18 188.55 16.05 1.37 0.90 0.62 95.12 17:35:01 dev8-0 1461.36 23261.93 251.86 16.09 1.57 1.08 0.65 95.49 и по sar 00:00:01 CPU %user %nice %system %iowait %steal %idle 15:35:01 all 3.27 0.00 0.36 0.14 0.00 96.23 15:45:01 all 4.03 0.00 0.73 0.14 0.00 95.10 15:55:01 all 3.94 0.00 0.70 0.16 0.00 95.20 16:05:01 all 4.28 0.00 0.90 0.13 0.00 94.69 16:15:01 all 4.24 0.00 0.88 0.13 0.00 94.75 16:25:01 all 4.37 0.00 0.87 0.19 0.00 94.57 16:35:01 all 4.10 0.00 0.81 0.13 0.00 94.95 16:45:01 all 4.13 0.00 0.79 0.11 0.00 94.96 16:55:01 all 4.16 0.00 0.79 0.20 0.00 94.84 17:05:01 all 4.37 0.00 0.85 0.31 0.00 94.47 17:15:01 all 5.26 0.00 1.67 11.84 0.00 81.24 17:25:01 all 4.95 0.00 1.55 11.86 0.00 81.64 17:35:01 all 4.72 0.00 1.38 12.04 0.00 81.86 Maxim Boguk4)iostat -x -m 1 во время проблемы отсчетов 10-20 как скажите > iostat -x -m 1 -c 1 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.93 0.00 91.28 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 172.33 22.49 3.74 3.54 76.56 2.72 13.96 2.58 101.14 1.06 20.69 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.93 0.00 91.28 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 172.49 22.49 3.74 3.54 76.50 2.72 13.95 2.58 101.14 1.06 20.70 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.93 0.00 91.28 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 172.58 22.49 3.74 3.54 76.47 2.72 13.94 2.58 101.14 1.06 20.71 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.93 0.00 91.28 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 172.83 22.49 3.74 3.54 76.38 2.72 13.93 2.58 101.14 1.06 20.72 > iostat -x -m 1 -c 1 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.93 0.00 91.28 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 172.86 22.48 3.74 3.54 76.37 2.72 13.92 2.58 101.14 1.06 20.72 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.93 0.00 91.28 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 172.92 22.48 3.74 3.54 76.35 2.72 13.92 2.58 101.14 1.06 20.73 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.93 0.00 91.28 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 172.93 22.48 3.74 3.54 76.34 2.72 13.92 2.58 101.14 1.06 20.73 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.93 0.00 91.28 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 173.00 22.48 3.74 3.54 76.32 2.72 13.91 2.58 101.14 1.06 20.73 avg-cpu: %user %nice %system %iowait %steal %idle 4.14 0.00 0.65 3.94 0.00 91.27 Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util sda 0.52 5.27 173.83 22.48 3.75 3.54 76.03 2.72 13.85 2.57 101.13 1.06 20.78 Maxim Boguk5)вывод SELECT (now() - pg_stat_activity.xact_start) AS age, pg_stat_activity.datname, pg_stat_activity.procpid, pg_stat_activity.usename, pg_stat_activity.waiting, pg_stat_activity.query_start, pg_stat_activity.client_addr, pg_stat_activity.client_port, pg_stat_activity.current_query FROM pg_stat_activity WHERE ((pg_stat_activity.xact_start IS NOT NULL) AND ((now() - pg_stat_activity.xact_start) > '00:00:10'::interval)) and pg_stat_activity.procpid<>pg_backend_pid() ORDER BY pg_stat_activity.xact_start; ОШИБКА: колонка pg_stat_activity.procpid не существует ОШИБКА: колонка pg_stat_activity.current_query не существует ОШИБКА: колонка pg_stat_activity.procpid Поудаляв все эти колонки получил одну строку age datname usename waiting query_start client_addr client_port 04:33:04.91313 postgres postgres 0 2014-09-20 17:04:53.470526+04 -1 наверное, надо было какойто доппакет установить? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 20.09.2014, 21:52:49 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, Ага так... записи у вас на диски почти что нет. Хотя конечно я бы всеравно посоветовал поднять checkpoint_segments до 64 и checkpoint_timeout до 1h и checkpoint_completion_target до 0.9. По факту у вас откуда то прилетает пачка тяжелого линейного чтения (и скорее всего не одна) Почему линейного - 20.000 sector/s ваш рейд может только на линейном чтении давать. Если линейное (и мы предполагаем что это база) - скорее всего seq_scan. Я не обратил внимание что у вас 9.2 тогда как проблема начнется через минут 5 после начала сделайте от postgres: SELECT (now() - pg_stat_activity.xact_start) AS ts_age, pg_stat_activity.state, (now() - pg_stat_activity.query_start) as query_age, (now() - state_change) as change_age, pg_stat_activity.datname, pg_stat_activity.pid, pg_stat_activity.usename, pg_stat_activity.waiting, pg_stat_activity.client_addr, pg_stat_activity.client_port, pg_stat_activity.query FROM pg_stat_activity WHERE ((now() - pg_stat_activity.xact_start) > '00:00:10'::interval) and pg_stat_activity.pid<>pg_backend_pid() ORDER BY pg_stat_activity.xact_start LIMIT 10; Текущая теория - время от времени пользователи или ПО генерируют неожиданный/непроиндексированный запрос который вылетает в база seq scan по нескольким таблицам и начинает перегружать диск. PS: вообще полезно держать log_min_duratuion_statenent скажем в 1000 и анализировать логи базы на предмет длинныз запросов. Много чего интересного сможете узнать. --Maxim Boguk www.postgresql-consulting.ru ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.09.2014, 07:38:24 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Maxim Boguk, прилагаю анализ "зависа" насколько смог. Воздержался от своих выводов. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.09.2014, 13:32:32 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDelMaxim Boguk, прилагаю анализ "зависа" насколько смог. Воздержался от своих выводов. Покажите исходник JSONCURDERRINFO у вас а)партиционирование б)хранимка при этом для сочетания а+б вы совершенно неверно проверяете explain analyze... попробуйте проверить самый первый запрос следуюшим образом вместо explain SELECT s from strdat where did=134 and cid=28624 and datetime<=1411117512 order by datetime desc limit 1 сделайте prepare test(int,int,int) as SELECT s from strdat where did=134 and cid=28624 and datetime<=1411117512 order by datetime desc limit 1 и после этого explain (analyze, costs, buffers, timing) execute qqq(134,28624,1411117512); и покажите что у вас нарисовалось. Аналогично сделайте для первого запроса из GetBottomInfo. Я боюсь что результаты вас неприятно удивят. Если нет - будем смотреть дальше. --Maxim Boguk www.postgresql-consulting.ru ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.09.2014, 13:58:05 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Maxim BogukAltCtrlDelMaxim Boguk, прилагаю анализ "зависа" насколько смог. Воздержался от своих выводов. Покажите исходник JSONCURDERRINFO у вас а)партиционирование б)хранимка при этом для сочетания а+б вы совершенно неверно проверяете explain analyze... попробуйте проверить самый первый запрос следуюшим образом вместо explain SELECT s from strdat where did=134 and cid=28624 and datetime<=1411117512 order by datetime desc limit 1 сделайте prepare test(int,int,int) as SELECT s from strdat where did=134 and cid=28624 and datetime<=1411117512 order by datetime desc limit 1 и после этого explain (analyze, costs, buffers, timing) execute qqq(134,28624,1411117512); и покажите что у вас нарисовалось. Аналогично сделайте для первого запроса из GetBottomInfo. Я боюсь что результаты вас неприятно удивят. Если нет - будем смотреть дальше. --Maxim Boguk www.postgresql-consulting.ru тьфу забыл после copy/paste поправить не Код: plsql 1. а Код: plsql 1. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.09.2014, 13:59:46 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Maxim Boguk, хранимки CREATE OR REPLACE FUNCTION GetBottomInfo(did_ integer) RETURNS SETOF varchar LANGUAGE plpgsql AS $$ DECLARE t integer; BEGIN select max(datetime) into t from dat where did=did_ and cid=0; if t is null then t:=0; end if; RETURN NEXT t; SELECT v into t from dat where did=did_ and cid=32463 order by datetime desc limit 1; if (not found) or (t is null) then t:=0; end if; RETURN NEXT t; END; $$; CREATE OR REPLACE FUNCTION JSONCURDERRINFO(d_id integer, mintime integer, maxtime integer, actionmask integer) RETURNS varchar LANGUAGE plpgsql AS $$ DECLARE r varchar; hname varchar; x real; i integer; BEGIN r:=''; if (actionmask & 1)<>0 then hname:=''; SELECT s into hname from strdat where did=d_id and cid=28624 and datetime<=maxtime order by datetime desc limit 1; if hname is null then hname:=''; end if; r:=r||',"hname":'||JSONQUOTE(hname); end if; if (actionmask & 2)<>0 then x:=0; SELECT v into x from dat where did=d_id and cid=28160 and datetime<=maxtime order by datetime desc limit 1; if x is null then x:=0; end if; r:=r||',"runnum":'||trunc(x); end if; if (actionmask & 4)<>0 then x:=0; SELECT max(deep) into x from dat where did=d_id and cid=0 and datetime between mintime and maxtime; if x is null then x:=0; end if; r:=r||',"bottomdeep":'||trunc(x::numeric,2); end if; if (actionmask & 8)<>0 then x:=0; SELECT v into x from dat where did=d_id and cid=1549 and datetime<=maxtime order by datetime desc limit 1; if x is null then x:=0; end if; r:=r||',"otkl0":'||trunc(x); end if; if (actionmask & 16)<>0 then x:=0; SELECT v into x from dat where did=d_id and cid=1550 and datetime<=maxtime order by datetime desc limit 1; if x is null then x:=0; end if; r:=r||',"dOtkl":'||trunc(x); end if; if (actionmask & 32)<>0 then i:=10; SELECT op into i from dat where did=d_id and datetime<=maxtime order by datetime desc limit 1; if i is null then i:=10; end if; r:=r||',"op":'||i; end if; if (actionmask & 64)<>0 then -- 26.04.2014 x:=0; SELECT v into x from dat where did=d_id and cid=32462 and datetime<=maxtime order by datetime desc limit 1; if x is null then x:=0; end if; r:=r||',"nadzab":'||trunc(x::numeric,2); end if; RETURN r; END; $$; Код: plsql 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. 11. 12. результат PREPARE QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.21 rows=1 width=28) (actual time=0.028..0.028 rows=1 loops=1) Buffers: shared hit=7 -> Result (cost=0.01..11.76 rows=58 width=28) (actual time=0.026..0.026 rows=1 loops=1) Buffers: shared hit=7 -> Merge Append (cost=0.01..11.76 rows=58 width=28) (actual time=0.025..0.025 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=7 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.015..0.015 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=4 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.76 rows=57 width=19) (actual time=0.009..0.009 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=3 Total runtime: 0.088 ms (15 rows) PREPARE QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------------- Result (cost=0.04..0.05 rows=1 width=0) (actual time=0.045..0.045 rows=1 loops=1) Buffers: shared hit=6 InitPlan 1 (returns $0) -> Limit (cost=0.01..0.04 rows=1 width=4) (actual time=0.043..0.043 rows=1 loops=1) Buffers: shared hit=6 -> Merge Append (cost=0.01..443071.24 rows=12929831 width=4) (actual time=0.043..0.043 rows=1 loops=1) Sort Key: public.dat.datetime Buffers: shared hit=6 -> Index Only Scan Backward using dat_pkey on dat (cost=0.00..4.26 rows=1 width=4) (actual time=0.009..0.009 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime IS NOT NULL) AND (cid = 0)) Heap Fetches: 0 Buffers: shared hit=1 -> Index Scan Backward using dat_134_0 on dat_134 dat (cost=0.00..281444.08 rows=12929830 width=4) (actual time=0.033..0.033 rows=1 loops=1) Index Cond: (datetime IS NOT NULL) Filter: (did = 134) Buffers: shared hit=5 Total runtime: 0.090 ms (17 rows) PREPARE QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.21 rows=1 width=28) (actual time=0.023..0.023 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..11.76 rows=58 width=28) (actual time=0.020..0.020 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..11.76 rows=58 width=28) (actual time=0.020..0.020 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.006..0.006 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.76 rows=57 width=19) (actual time=0.012..0.012 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=2 Total runtime: 0.072 ms (15 rows) PREPARE QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------------- Result (cost=0.04..0.05 rows=1 width=0) (actual time=0.025..0.025 rows=1 loops=1) Buffers: shared hit=5 InitPlan 1 (returns $0) -> Limit (cost=0.01..0.04 rows=1 width=4) (actual time=0.024..0.024 rows=1 loops=1) Buffers: shared hit=5 -> Merge Append (cost=0.01..443071.24 rows=12929831 width=4) (actual time=0.023..0.023 rows=1 loops=1) Sort Key: public.dat.datetime Buffers: shared hit=5 -> Index Only Scan Backward using dat_pkey on dat (cost=0.00..4.26 rows=1 width=4) (actual time=0.007..0.007 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime IS NOT NULL) AND (cid = 0)) Heap Fetches: 0 Buffers: shared hit=1 -> Index Scan Backward using dat_134_0 on dat_134 dat (cost=0.00..281444.08 rows=12929830 width=4) (actual time=0.015..0.015 rows=1 loops=1) Index Cond: (datetime IS NOT NULL) Filter: (did = 134) Buffers: shared hit=4 Total runtime: 0.068 ms (17 rows) ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.09.2014, 17:56:34 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, Hm а с каким интервалом у вас новые партиции создаются? Нет ли связи между появлением новых партиций в strdat и началом проблем... hm а если сделать вот так вот: --- Т.к. числа 28624 и 0 (коды cid) заданы жёстко (не параметрами), то проверяю их задание в prepare prepare test3(int,int) as SELECT s from strdat where did=$1 and cid=28624 and datetime<=$2 order by datetime desc limit 1; --3 раза для надежности... (тут планы особо не интересны кроме случая если он сменится вдруг) explain (analyze, costs, buffers, timing) execute test3(134,1411117512); explain (analyze, costs, buffers, timing) execute test3(134,1411117512); explain (analyze, costs, buffers, timing) execute test3(134,1411117512); --теперь эмулируем появление новой партиции (135)... если план совсем другой стал то приведите его 1 раз explain (analyze, costs, buffers, timing) execute test3(135,1411117512); explain (analyze, costs, buffers, timing) execute test3(135,1411117512); --и еще раз для старой партиции explain (analyze, costs, buffers, timing) execute test3(134,1411117512); Я собственно уже на 95% уверен в чем у вас проблема, так что следующий раз если проблема проявятся вместо рестарта и реиндекса базы попробуйте выполнить от postgres сброс всех коннектов к базе: select pg_terminate_backend(pid) from pg_stat_activity where usename<>'postgres'; и возможно она исправится (в общем они никак не связана с индексами вообще). --Maxim Boguk www.postgresql-consulting.ru ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.09.2014, 18:45:58 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Maxim Bogukа с каким интервалом у вас новые партиции создаются? Партиции - это объекты мониторинга. Реально, физические объекты обвешанные датчиками, данные с которых и сохраняются. Партиции создаются только вызовом хранимки create_part, я её приводил ранее. По логу, за последнии двое суток новых партиций не создавалось, а висло 5 раз. Создают вручную, подключая новые объекты. Раз в несколько дней. Может несколько в день случится. JSONCURDERRINFO, (из которой вызывается и SELECT s from strdat where did=$1 and cid=28624 and datetime<=$2 order by datetime desc limit 1), после старта приложения, для одной партиции, вызывается, почти всегда один раз, когда клиент обращается первый раз к этому объекту (этой партиции). Дальше данные кешируются на уровне приложения. Код: sql 1. 2. 3. 4. 5. 6. 7. 8. 9. 10. PREPARE QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.21 rows=1 width=28) (actual time=0.027..0.028 rows=1 loops=1) Buffers: shared hit=7 -> Result (cost=0.01..11.76 rows=58 width=28) (actual time=0.025..0.025 rows=1 loops=1) Buffers: shared hit=7 -> Merge Append (cost=0.01..11.76 rows=58 width=28) (actual time=0.025..0.025 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=7 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.014..0.014 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=4 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.76 rows=57 width=19) (actual time=0.008..0.008 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=3 Total runtime: 0.083 ms (15 rows) QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.21 rows=1 width=28) (actual time=0.019..0.019 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..11.76 rows=58 width=28) (actual time=0.018..0.018 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..11.76 rows=58 width=28) (actual time=0.017..0.017 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.006..0.006 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.76 rows=57 width=19) (actual time=0.010..0.010 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=2 Total runtime: 0.065 ms (15 rows) QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.21 rows=1 width=28) (actual time=0.019..0.019 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..11.76 rows=58 width=28) (actual time=0.017..0.017 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..11.76 rows=58 width=28) (actual time=0.016..0.016 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.006..0.006 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.76 rows=57 width=19) (actual time=0.010..0.010 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=2 Total runtime: 0.064 ms (15 rows) QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.19 rows=1 width=26) (actual time=0.025..0.025 rows=1 loops=1) Buffers: shared hit=4 -> Result (cost=0.01..11.84 rows=67 width=26) (actual time=0.023..0.023 rows=1 loops=1) Buffers: shared hit=4 -> Merge Append (cost=0.01..11.84 rows=67 width=26) (actual time=0.023..0.023 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=4 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.005..0.005 rows=0 loops=1) Index Cond: ((did = 226) AND (datetime <= 1411292950) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_226_28624 on strdat_226 strdat (cost=0.00..6.73 rows=66 width=19) (actual time=0.016..0.016 rows=1 loops=1) Index Cond: (datetime <= 1411292950) Filter: (did = 226) Buffers: shared hit=3 Total runtime: 0.067 ms (15 rows) QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.19 rows=1 width=26) (actual time=0.015..0.016 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..11.84 rows=67 width=26) (actual time=0.013..0.013 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..11.84 rows=67 width=26) (actual time=0.012..0.012 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.005..0.005 rows=0 loops=1) Index Cond: ((did = 226) AND (datetime <= 1411292950) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_226_28624 on strdat_226 strdat (cost=0.00..6.73 rows=66 width=19) (actual time=0.006..0.006 rows=1 loops=1) Index Cond: (datetime <= 1411292950) Filter: (did = 226) Buffers: shared hit=2 Total runtime: 0.054 ms (15 rows) QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.21 rows=1 width=28) (actual time=0.012..0.012 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..11.76 rows=58 width=28) (actual time=0.011..0.011 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..11.76 rows=58 width=28) (actual time=0.011..0.011 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.004..0.004 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.76 rows=57 width=19) (actual time=0.005..0.005 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=2 Total runtime: 0.049 ms (15 rows) QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.21 rows=1 width=28) (actual time=0.019..0.019 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..11.76 rows=58 width=28) (actual time=0.018..0.018 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..11.76 rows=58 width=28) (actual time=0.017..0.017 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.006..0.006 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.76 rows=57 width=19) (actual time=0.010..0.010 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=2 Total runtime: 0.068 ms (15 rows) Maxim BogukЯ собственно уже на 95% уверен в чем у вас проблема, так что следующий раз если проблема проявятся вместо рестарта и реиндекса базы попробуйте выполнить от postgres сброс всех коннектов к базе: select pg_terminate_backend(pid) from pg_stat_activity where usename<>'postgres'; Это уронит оба серверных приложения. Тогда проще их остановить и выполнить то что Вы указываете. (Если не лучше перезапустить постгрес?) и запустить их снова. Вообще то проблем нет такой скрипт соорудить. Знать бы критерий когда запускать. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.09.2014, 19:49:43 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Сегодня несколько раз пытался, при загрузке дисков 100%, просто перезапускать постгрес без реиндекса - работы хватает на полчаса. Сейчас пробовал select pg_terminate_backend(pid) from pg_stat_activity where usename<>'postgres'; после остановки приложений. по данным pg_stat_activity и после этого остаются висеть "зависшие" селекты. Только перезапуск постгреса их прибивает. Запустил Код: sql 1. 2. 3. Хотя, это без толку. Опять скоро зависнет. Наверное, только абгрейт железа поможет. Или железо глючит? На винтах ничего подозрительного не горит. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 21.09.2014, 20:30:27 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, Меня очень смущают те планы что вы привели (т.е. такого просто не может быть). Вы точно делали prepare 1 раз а explain analyze c разными did несколько раз? Так как план должен был поменяться в какой то момент на перебор всех партиций (причем необратимо поменяться). Попробуйте для очистки освести погонять explain analyze однажды prepared запроса с разными did. --Maxim Boguk www.postgresql-consulting.ru ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 04:24:43 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel<>после этого остаются висеть "зависшие" селекты. Только перезапуск постгреса их прибивает. <> с этого места поподробнее, пжалста перловые ф-ии ? внешние сервера от ара-кала? что левого к базе прикрутили, признавайтесь -- вот на этом всём где-то вы и висите, думается ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 08:18:59 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
думаетсяAltCtrlDel<>после этого остаются висеть "зависшие" селекты. Только перезапуск постгреса их прибивает. <> с этого места поподробнее, пжалста перловые ф-ии ? внешние сервера от ара-кала? что левого к базе прикрутили, признавайтесь -- вот на этом всём где-то вы и висите, думается версия -- повисшие -- автономки, запускаемые из security defined ф-ий из-под postgres, процессы которого вы не прибивали. И они у вас в неразрешимом дедлоке (что от реиндекса не зависит), либо в очередях на уникъю, что от реиндекса немного зависит. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 08:24:12 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
что-то я не точен в высказываниях еще поправка/уточнение/ версии про автономки повисшие, которые не постгреса, -- запускаются с sec/def/ , написаны от постгреса, которые запустили свои автономки и ждут (терминейтом не кладутся, не получив возврат от автономок). если бы вы прибили их детей -- они бы и легли. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 08:29:02 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Maxim BogukAltCtrlDel, Меня очень смущают те планы что вы привели (т.е. такого просто не может быть). Вы точно делали prepare 1 раз а explain analyze c разными did несколько раз? Так как план должен был поменяться в какой то момент на перебор всех партиций (причем необратимо поменяться). Попробуйте для очистки освести погонять explain analyze однажды prepared запроса с разными did. Я сохраняю приведённый скрипт в файл и выполняю его с помощью psql. Вот, ещё Код: sql 1. 2. 3. 4. 5. 6. 7. 8. 9. PREPARE QUERY PLAN ------------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.18 rows=1 width=26) (actual time=18.807..18.807 rows=1 loops=1) Buffers: shared hit=5 read=2 -> Result (cost=0.01..12.08 rows=73 width=26) (actual time=18.806..18.806 rows=1 loops=1) Buffers: shared hit=5 read=2 -> Merge Append (cost=0.01..12.08 rows=73 width=26) (actual time=18.806..18.806 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=5 read=2 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.023..0.023 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=4 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.90 rows=72 width=19) (actual time=18.781..18.781 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=1 read=2 Total runtime: 18.868 ms (15 rows) QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..2.16 rows=1 width=144) (actual time=0.046..0.047 rows=1 loops=1) Buffers: shared hit=3 read=1 -> Result (cost=0.01..8.60 rows=4 width=144) (actual time=0.044..0.044 rows=1 loops=1) Buffers: shared hit=3 read=1 -> Merge Append (cost=0.01..8.60 rows=4 width=144) (actual time=0.042..0.042 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 read=1 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.006..0.006 rows=0 loops=1) Index Cond: ((did = 210) AND (datetime <= 1399399261) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_210_28624 on strdat_210 strdat (cost=0.00..4.28 rows=3 width=19) (actual time=0.036..0.036 rows=1 loops=1) Index Cond: (datetime <= 1399399261) Filter: (did = 210) Buffers: shared hit=2 read=1 Total runtime: 0.094 ms (15 rows) QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.88 rows=1 width=69) (actual time=0.032..0.032 rows=1 loops=1) Buffers: shared hit=4 -> Result (cost=0.01..8.73 rows=10 width=69) (actual time=0.031..0.031 rows=1 loops=1) Buffers: shared hit=4 -> Merge Append (cost=0.01..8.73 rows=10 width=69) (actual time=0.029..0.029 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=4 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.005..0.005 rows=0 loops=1) Index Cond: ((did = 223) AND (datetime <= 1410961708) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_223_28624 on strdat_223 strdat (cost=0.00..4.33 rows=9 width=19) (actual time=0.024..0.024 rows=1 loops=1) Index Cond: (datetime <= 1410961708) Filter: (did = 223) Buffers: shared hit=3 Total runtime: 0.077 ms (15 rows) QUERY PLAN -------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=2.27..2.27 rows=1 width=270) (actual time=227.332..227.333 rows=1 loops=1) Buffers: shared hit=1 read=18 -> Sort (cost=2.27..2.27 rows=2 width=270) (actual time=227.330..227.330 rows=1 loops=1) Sort Key: public.strdat.datetime Sort Method: top-N heapsort Memory: 25kB Buffers: shared hit=1 read=18 -> Result (cost=0.00..2.26 rows=2 width=270) (actual time=16.240..227.257 rows=29 loops=1) Buffers: shared hit=1 read=18 -> Append (cost=0.00..2.26 rows=2 width=270) (actual time=16.239..227.241 rows=29 loops=1) Buffers: shared hit=1 read=18 -> Seq Scan on strdat (cost=0.00..0.00 rows=1 width=520) (actual time=0.001..0.001 rows=0 loops=1) Filter: ((datetime <= 1411292950) AND (did = 226) AND (cid = 28624)) -> Index Scan Backward using strdat_226_28624 on strdat_226 strdat (cost=0.00..2.26 rows=1 width=19) (actual time=16.237..227.226 rows=29 loops=1) Index Cond: (datetime <= 1411292950) Filter: (did = 226) Buffers: shared hit=1 read=18 Total runtime: 227.369 ms (17 rows) QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.18 rows=1 width=26) (actual time=0.015..0.015 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..12.08 rows=73 width=26) (actual time=0.014..0.014 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..12.08 rows=73 width=26) (actual time=0.014..0.014 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.006..0.006 rows=0 loops=1) Index Cond: ((did = 134) AND (datetime <= 1411117512) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_134_28624 on strdat_134 strdat (cost=0.00..6.90 rows=72 width=19) (actual time=0.008..0.008 rows=1 loops=1) Index Cond: (datetime <= 1411117512) Filter: (did = 134) Buffers: shared hit=2 Total runtime: 0.042 ms (15 rows) QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..2.16 rows=1 width=144) (actual time=0.010..0.011 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..8.60 rows=4 width=144) (actual time=0.009..0.009 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..8.60 rows=4 width=144) (actual time=0.009..0.009 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.005..0.005 rows=0 loops=1) Index Cond: ((did = 210) AND (datetime <= 1399399261) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_210_28624 on strdat_210 strdat (cost=0.00..4.28 rows=3 width=19) (actual time=0.004..0.004 rows=1 loops=1) Index Cond: (datetime <= 1399399261) Filter: (did = 210) Buffers: shared hit=2 Total runtime: 0.048 ms (15 rows) QUERY PLAN ---------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=0.01..0.88 rows=1 width=69) (actual time=0.010..0.010 rows=1 loops=1) Buffers: shared hit=3 -> Result (cost=0.01..8.73 rows=10 width=69) (actual time=0.009..0.009 rows=1 loops=1) Buffers: shared hit=3 -> Merge Append (cost=0.01..8.73 rows=10 width=69) (actual time=0.009..0.009 rows=1 loops=1) Sort Key: public.strdat.datetime Buffers: shared hit=3 -> Index Scan Backward using strdat_pkey on strdat (cost=0.00..4.26 rows=1 width=520) (actual time=0.004..0.004 rows=0 loops=1) Index Cond: ((did = 223) AND (datetime <= 1410961708) AND (cid = 28624)) Buffers: shared hit=1 -> Index Scan Backward using strdat_223_28624 on strdat_223 strdat (cost=0.00..4.33 rows=9 width=19) (actual time=0.004..0.004 rows=1 loops=1) Index Cond: (datetime <= 1410961708) Filter: (did = 223) Buffers: shared hit=2 Total runtime: 0.034 ms (15 rows) QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------------- Limit (cost=2.27..2.27 rows=1 width=270) (actual time=0.035..0.036 rows=1 loops=1) Buffers: shared hit=18 -> Sort (cost=2.27..2.27 rows=2 width=270) (actual time=0.035..0.035 rows=1 loops=1) Sort Key: public.strdat.datetime Sort Method: top-N heapsort Memory: 25kB Buffers: shared hit=18 -> Result (cost=0.00..2.26 rows=2 width=270) (actual time=0.005..0.028 rows=29 loops=1) Buffers: shared hit=18 -> Append (cost=0.00..2.26 rows=2 width=270) (actual time=0.005..0.027 rows=29 loops=1) Buffers: shared hit=18 -> Seq Scan on strdat (cost=0.00..0.00 rows=1 width=520) (actual time=0.000..0.000 rows=0 loops=1) Filter: ((datetime <= 1411292950) AND (did = 226) AND (cid = 28624)) -> Index Scan Backward using strdat_226_28624 on strdat_226 strdat (cost=0.00..2.26 rows=1 width=19) (actual time=0.004..0.023 rows=29 loops=1) Index Cond: (datetime <= 1411292950) Filter: (did = 226) Buffers: shared hit=18 Total runtime: 0.056 ms (17 rows) Maxim Bogukс этого места поподробнее, пжалста перловые ф-ии ? внешние сервера от ара-кала? что левого к базе прикрутили, признавайтесь К постгресу ничего не прикручивал и даже не из сорцов его ставил. Признаюсь, что я не пробрасывал порты к серверу и всё делаю из Webmin-а. Может из за этого? Я остановил апач, остановил приложение пишушее в базу. Они остановились (проверял по списку процессов), зашёл в Webmin-e Службы\Сервер баз данных PostgreSQL\postgres\Исполнить SQL, вставил Код: sql 1. - выполнилось. Посмотрел так же Код: sql 1. - селекты висели. Может, подождать надо было. Но мне хотелось систему восстановить, я перезапустил постгрес. Maxim Bogukверсия -- повисшие -- автономки, запускаемые из security defined ф-ий из-под postgres, процессы которого вы не прибивали. И они у вас в неразрешимом дедлоке (что от реиндекса не зависит), либо в очередях на уникъю, что от реиндекса немного зависит. еще поправка/уточнение/ версии про автономки повисшие, которые не постгреса, -- запускаются с sec/def/ , написаны от постгреса, которые запустили свои автономки и ждут (терминейтом не кладутся, не получив возврат от автономок). если бы вы прибили их детей -- они бы и легли. Тут я "поплыл". Что такое security defined ф-ий, которые запускаются с sec/def/ ? Все эти селекты вызываются из мода апача, который использует для доступа к постгресу http://apr.apache.org/docs/apr/2.0/group___a_p_r___util___d_b_d.html , и вообще библиотеку apr на которой сам апач работает. Апач я закрыл. Может он ещё не успел полностью закрыться? Попробую при следующем падении. Логично напрашивается вопрос - нельзя ли прибивать "застрявшие" запросы к базе а не коннекты к ней? Ну и отчего они застревают то? Ничего со словом security не использовалось. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 13:52:54 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Снова загрузка 100%. Остановил апач, прибил все его процессы, закрыл второе приложение. Всё что работает с базой прибито. По pg_stat_activity выдаётся ts_age state query_age change_age datname pid usename waiting client_addr client_port query 01:15:11.548306 active 01:15:11.548306 01:15:11.548306 postgres 13510 postgres 0 -1 select GetBottomInfo(201) Код: sql 1. - выполняется но эффекта нет. В списке процессов, на первом месте по загрузке проца ID Владелец Использование CPU Команда 13510 postgres 4.9 % postgres: postgres postgres [local] SELECT Если дедлок, то он же с чем то должен сцепиться? Не сам же с собой? Или с аутовакуумом? Опять, же почему загрузка проца большая? Я не знаю, где копать. autovacuum = on #log_autovacuum_min_duration = -1 autovacuum_max_workers = 4 autovacuum_naptime = 5s # Сброс в базу в приложении каждые 5 секунд, поэтому. Хотя, может неправильно. autovacuum_vacuum_threshold = 50 autovacuum_analyze_threshold = 10 autovacuum_vacuum_scale_factor = 0.02 autovacuum_analyze_scale_factor = 0.02 #autovacuum_freeze_max_age = 200000000 autovacuum_vacuum_cost_delay = 10ms #autovacuum_vacuum_cost_limit = -1 ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 14:27:22 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDelСнова загрузка 100%. Остановил апач, прибил все его процессы, закрыл второе приложение. Всё что работает с базой прибито. По pg_stat_activity выдаётся ts_age state query_age change_age datname pid usename waiting client_addr client_port query 01:15:11.548306 active 01:15:11.548306 01:15:11.548306 postgres 13510 postgres 0 -1 select GetBottomInfo(201) Код: sql 1. - выполняется но эффекта нет. В списке процессов, на первом месте по загрузке проца ID Владелец Использование CPU Команда 13510 postgres 4.9 % postgres: postgres postgres [local] SELECT Если дедлок, то он же с чем то должен сцепиться? Не сам же с собой? Или с аутовакуумом? Опять, же почему загрузка проца большая? Я не знаю, где копать. autovacuum = on #log_autovacuum_min_duration = -1 autovacuum_max_workers = 4 autovacuum_naptime = 5s # Сброс в базу в приложении каждые 5 секунд, поэтому. Хотя, может неправильно. autovacuum_vacuum_threshold = 50 autovacuum_analyze_threshold = 10 autovacuum_vacuum_scale_factor = 0.02 autovacuum_analyze_scale_factor = 0.02 #autovacuum_freeze_max_age = 200000000 autovacuum_vacuum_cost_delay = 10ms #autovacuum_vacuum_cost_limit = -1 скорее всего что копать надо в сторону переделки хранимок ваших на execute 'sql' using variables; для тех запросов внутри хранимок которые партиционированные таблицы цепляют. --Maxim Boguk www.postgresql-consulting.ru ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 15:34:29 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Как я ранее написал, оставалось висеть select GetBottomInfo(201). Я перезапустил приложения и постгрес. Через пол часа опять 100% загрузка, всё снимаю, остаются висеть уже ДВА select GetBottomInfo(201). И именно 201. Что это как не испорченный индекс (или сама таблица?)? Запустил reindex table dat_201 - выполнилась быстро. Запустил систему снова. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 16:22:54 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDelКак я ранее написал, оставалось висеть select GetBottomInfo(201). Я перезапустил приложения и постгрес. Через пол часа опять 100% загрузка, всё снимаю, остаются висеть уже ДВА select GetBottomInfo(201). И именно 201. Что это как не испорченный индекс (или сама таблица?)? Запустил reindex table dat_201 - выполнилась быстро. Запустил систему снова. когда проблема проявится опять попробуйте руками прогнать выполнение залипающих запросов (До рестарта базы и reindex) если они не залипают - значит проблема не в индексах если залипают руками пройдитесь по всем запросам внутри хранимки и попробуйте найти тот что залипает и через explain посмотреть его план. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 20:16:47 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Совет запоздал. я просто прибил партицию 201 (select count(*) from dat_201 показывало 0) и, вот уже два часа система работает с загрузкой винтов около процента. Перед этим я много раз делал реиндексы и полные и для этой таблицы только. Не помогало. Ощущение что повредилась сама таблица dat_201, а не индексы. Так может быть? Если да, то отчего? Опять же, получается что CLUSTER такое не лечит. Не понятно как искать если снова случится. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 22.09.2014, 21:09:25 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, > 201 а это старая/новая партиция? что-то в ней есть особенного по ddl (sql-схеме) или по природе исходного "датчика"? когда последний раз в неё лилось и как много? были ли по ней массовые апдейты/делиты? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.09.2014, 01:53:34 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, какой у вас 9.2? как вы, откуда и когда на него апгрейдились? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.09.2014, 01:55:53 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
Misha TyurinAltCtrlDel, а это старая/новая партиция? что-то в ней есть особенного по ddl (sql-схеме) или по природе исходного "датчика"? Такой истории не имею. Партиция обычная, они все одинаковые, создаются хранимкой, в одном из постов выше я её приводил - create_part (в файле analiz.zip, прикреплённом к посту). Как я выше писал, вроде бы, пустая была (select count(*) from dat_201 показывало 0). Партиции нумеруются последовательно, по мере создания, сейчас последняя 244. Зная, к какому объекту она относилась, попытаюсь узнать, писалось ли что то в неё у пользователей. Вообще это ненормально, что 0 записей. Приложение создаёт партицию когда начинают идти данные от нового объекта и никогда не удаляет частями из партиции. На объект создаётся две партиции разных таблиц. dat и strdat, проблема была с dat (таблица партиции dat_201). Упрощённо - в dat информация в виде чисел, в strdat - в виде текстовых строк. Обычно записей в dat раз в 100 больше, и извлекаются чаще, так что вся нагрузка от dat. (cм. analiz.zip) В последнее время из dat_201 пытались делать выборки - оттого и висло. Удалил я корректно, без нарушения структуры базы, т.е. и запись в таблице на неё ссылающеюся. PostgreSQL 9.2.4 on x86_64-unknown-linux-gnu, compiled by gcc (Ubuntu/Linaro 4.6.3-1ubuntu5) 4.6.3, 64-bit Ранее был 9.1, но переход выполнялся давно (в конце мая 2013) и всё работало. Перенос через pg_dump - pg_restore. ps: до сих пор работает, и загрузка не растёт. Прямо даже не верится. А то висло через полчаса. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.09.2014, 05:12:53 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, дело скорее всего не в индексах. посмотрел на вашу висящую (код) -- если висит только она, то ничего внешнего там не дергается, при этом waiting у нее --0. При 240 партициях я бы ожидал массу неприятностей от планировщика, если не адресоваться к партиции (руками) явно. (при порядка 100 парт. и по 6 индексов на партицию время (первичного) планирования , если все требуемые системные/статистические данные не в кеше, среднесложного запроса -- 10-ок с гаком секунд). Правда у вас запросы -- проще некуда. Версия -- тупит планировщик (на этапе собственно выполнения терминейт не обламывался ни разу, если прибиваемый процесс не ждёт ответа от другого процесса -- о чём я, было, подумал). Попробуйте обновиться, чес чёрт не шутит. Попробуйте выполнять через динамич. скл. -- тоже верная рекомендация для партицированных. можно наверное включить модуль фиксации планов во время выполнения -- попытаться понять, что там происходит. (на память не вспомню, поковыряюсь в загашнике, не уверен, что он фиксирует планы "внутре" ф-й.) ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.09.2014, 08:29:10 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, вооо... всё таки отличие какое-то есть. странный "0" строк. я бы разобрался с эти, откуда такое прилетело. это как минимум интересно, ну и может потенциально предупредить возобновление проблемы. как это говорится, вангую, что дело именно в этом нуле или где-то около этого обстоятельства. у вас мог где-то вдруг индекскан начать перебирать всю пустоту в поисках нужного тупла. хотя вы и писали, что всё реиндексили, вакуумили, анализировали и прочее. возможно еще что из-за этого нуля.... нда. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.09.2014, 13:15:29 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
AltCtrlDel, А вы bloat проверяли для таблиц/индексов? Возможно, в партицию 201 была попытка загрузить большой объем данных, но по какой-то причине транзакцию убили/отменили. Тогда при нулевом кол-ве видимых записей и в таблице, и в индексе будет много "deleted" кортежей (tuples). Это и место, и поиск в FSM. У вас нету временных ограничений на работу процедур загрузки данных в приложении? ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.09.2014, 14:32:29 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
думаетсяПри 240 партициях я бы ожидал массу неприятностей от планировщика, если не адресоваться к партиции (руками) явно. На самом деле, основное число выборок приходится на "SELECT cid,max(v),min(datetime) FROM dat_%s where (cid in (0,1,2,100)) and datetime between %d and %d group by cid,datetime / %d order by min(datetime)" где %s - номер партиции, и т.д. В конфиге стоит log_min_duration_statement = 1000, по этому они редко в лог попадают - выполняются быстро. А вот запись идёт в приложении через COPY dat FROM stdin with binary Приложение-сборщик собирает данные со всех активных своих клиентов по 5с, пишет во входной поток COPY. Т.е. тут неявное обращение к партициям потому что в потоке идут данные для разных партиций. Но приложение-сборщик то как раз не падало, оно грузит то на 0.1%, основное выборки. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.09.2014, 16:24:35 |
|
||
|
REINDEX DATABASE выполняется уже 6 часов и конца не видно
|
|||
|---|---|---|---|
|
#18+
vyegorovА вы bloat проверяли для таблиц/индексов? Нет. Думал что не нужно. Я выше писал что приложение никогда не удаляет отдельные записи из таблиц и не делает по ним UPDATE. vyegorovВозможно, в партицию 201 была попытка загрузить большой объем данных, но по какой-то причине транзакцию убили/отменили. Возможно. Опять же выше я писал, что часть пользователей имеет доступ к сереру и чуть что нажимали на нём ресет. Сейчас, вроде, отучили их от этого. vyegorovТогда при нулевом кол-ве видимых записей и в таблице, и в индексе будет много "deleted" кортежей (tuples). Это и место, и поиск в FSM. Сейчас уже поздно. И, честно говоря, я не знаю как и что смотреть в Free Space Map. vyegorovУ вас нету временных ограничений на работу процедур загрузки данных в приложении? нет. ... |
|||
|
:
Нравится:
Не нравится:
|
|||
| 23.09.2014, 16:33:45 |
|
||
|
|

start [/forum/topic.php?all=1&fid=53&tid=1998481]: |
0ms |
get settings: |
6ms |
get forum list: |
11ms |
check forum access: |
3ms |
check topic access: |
3ms |
track hit: |
178ms |
get topic data: |
8ms |
get forum data: |
2ms |
get page messages: |
52ms |
get tp. blocked users: |
1ms |
| others: | 209ms |
| total: | 473ms |

| 0 / 0 |
