Logo MurCode
PostgreSQL Новое сообщение

Быстрый запрос в explain analyze но медленный по факту

VerusK
Дата: 26.03.2015 08:10:08
Добрый день. Не могу понять в чем дело, копаюсь уже неделю, наверное. Есть БД в которой сейчас примерно 260 таблиц, есть такие таблицы как статистика, они унаследованы от основной таблицы статистики, т.е. в базе реализовано партицирование по времени и id юзера, получаются таблицы вида stats_y2015_m3_u1(год 2015, месяц 3, юзер 1), в каждой таблице есть CHECK CONSTRAINT, на основной таблице висит триггер на insert который проверяет есть ли такая таблица в которую надо сделать вставку, если нет, то создает ее и делает insert. Обновление примерно 1к строк для одного юзера занимает примерно 160сек(секунд), что как бы ооочень долго, я считаю. explain analyze показывает такие данные - http://explain.depesz.com/s/fnz т.е. выполняется запрос 0.115мсек(миллисекунд), если же я запускаю вставку на сервере, то по монитору вижу, что каждый такой запрос выполняется 0.1-0.2..сек(секунд). Postgresql 9.4.0,пробовал запускать на 9.3 и на 9.2 - результат такой же. Причем заметил, что если база чистая и партицированных таблиц нет, то вставка происходит намного быстрее.
лопата
Дата: 26.03.2015 08:30:25
VerusK,
поветрие пошло -- гребсти слова в кучку. И все -- ниочом.

приведите именно тот код, который, по вашему мнению, тормозит. Весь. будем посмотреть.

И да, в обновлении (партицирующих триггерах) предусмотрена возможность смены партиции ? или по месту не двигаетесь ?
VerusK
Дата: 26.03.2015 08:36:56
Код который выполняется:

UPDATE stats 
SET 
actions=(stats.actions + 0), offer_clicks=(stats.offer_clicks + 0), uniq=(stats.uniq + 0), raw=(stats.raw + 1), 
tb_uniq=(stats.tb_uniq + 0), tb_raw=(stats.tb_raw + 0), leads=(stats.leads + 0), subs=(stats.subs + 0), unsubs=(stats.unsubs + 0), 
rebills=(stats.rebills + 0), sales=(stats.sales + 0), holds=(stats.holds + 0), rejects=(stats.rejects + 0), trashes=(stats.trashes + 0),
user_lead_income=(stats.user_lead_income + 0.0), user_subs_income=(stats.user_subs_income + 0.0), 
user_rebill_income=(stats.user_rebill_income + 0.0), user_sales_income=(stats.user_sales_income + 0.0), 
user_hold_income=(stats.user_hold_income + 0.0), system_lead_income=(stats.system_lead_income + 0.0), 
system_subs_income=(stats.system_subs_income + 0.0), system_rebill_income=(stats.system_rebill_income + 0.0), 
system_sales_income=(stats.system_sales_income + 0.0), system_hold_income=(stats.system_hold_income + 0.0) 
WHERE 
stats.ts_spawn = 1426960800 AND stats.user_id = 1 AND stats.offer_targeting_id = 132 AND stats.offer_id = 123 AND 
stats.traff_type = 4 AND stats.operator_id = 0 AND stats.country_id = 113 AND 
stats.subacc_1 = '' AND stats.subacc_2 = '' AND stats.subacc_3 = '' AND stats.subacc_4 = '' AND stats.utm_source = '' AND
stats.utm_medium = '' AND stats.utm_term = '' AND stats.utm_content = '' AND stats.utm_campaign = '' AND 
stats.prelanding_id = 203 AND stats.landing_id = 0 AND stats.platform_id = 6 AND stats.platform_out_id = 76 AND 
stats.os_id = 9 AND stats.browser_id = 34
Maxim Boguk
Дата: 26.03.2015 09:08:58
VerusK
Код который выполняется:

UPDATE stats 
SET 
actions=(stats.actions + 0), offer_clicks=(stats.offer_clicks + 0), uniq=(stats.uniq + 0), raw=(stats.raw + 1), 
tb_uniq=(stats.tb_uniq + 0), tb_raw=(stats.tb_raw + 0), leads=(stats.leads + 0), subs=(stats.subs + 0), unsubs=(stats.unsubs + 0), 
rebills=(stats.rebills + 0), sales=(stats.sales + 0), holds=(stats.holds + 0), rejects=(stats.rejects + 0), trashes=(stats.trashes + 0),
user_lead_income=(stats.user_lead_income + 0.0), user_subs_income=(stats.user_subs_income + 0.0), 
user_rebill_income=(stats.user_rebill_income + 0.0), user_sales_income=(stats.user_sales_income + 0.0), 
user_hold_income=(stats.user_hold_income + 0.0), system_lead_income=(stats.system_lead_income + 0.0), 
system_subs_income=(stats.system_subs_income + 0.0), system_rebill_income=(stats.system_rebill_income + 0.0), 
system_sales_income=(stats.system_sales_income + 0.0), system_hold_income=(stats.system_hold_income + 0.0) 
WHERE 
stats.ts_spawn = 1426960800 AND stats.user_id = 1 AND stats.offer_targeting_id = 132 AND stats.offer_id = 123 AND 
stats.traff_type = 4 AND stats.operator_id = 0 AND stats.country_id = 113 AND 
stats.subacc_1 = '' AND stats.subacc_2 = '' AND stats.subacc_3 = '' AND stats.subacc_4 = '' AND stats.utm_source = '' AND
stats.utm_medium = '' AND stats.utm_term = '' AND stats.utm_content = '' AND stats.utm_campaign = '' AND 
stats.prelanding_id = 203 AND stats.landing_id = 0 AND stats.platform_id = 6 AND stats.platform_out_id = 76 AND 
stats.os_id = 9 AND stats.browser_id = 34


для начала сделайте 
explain (analyze, costs, buffers) select * from stats 
WHERE 
stats.ts_spawn = 1426960800 AND stats.user_id = 1 AND stats.offer_targeting_id = 132 AND stats.offer_id = 123 AND 
stats.traff_type = 4 AND stats.operator_id = 0 AND stats.country_id = 113 AND 
stats.subacc_1 = '' AND stats.subacc_2 = '' AND stats.subacc_3 = '' AND stats.subacc_4 = '' AND stats.utm_source = '' AND
stats.utm_medium = '' AND stats.utm_term = '' AND stats.utm_content = '' AND stats.utm_campaign = '' AND 
stats.prelanding_id = 203 AND stats.landing_id = 0 AND stats.platform_id = 6 AND stats.platform_out_id = 76 AND 
stats.os_id = 9 AND stats.browser_id = 34


и пришлите его сюда.

--Maxim Boguk
www.postgresql-consulting.ru
Maxim Boguk
Дата: 26.03.2015 09:13:25
VerusK
Добрый день. Не могу понять в чем дело, копаюсь уже неделю, наверное. Есть БД в которой сейчас примерно 260 таблиц, есть такие таблицы как статистика, они унаследованы от основной таблицы статистики, т.е. в базе реализовано партицирование по времени и id юзера, получаются таблицы вида stats_y2015_m3_u1(год 2015, месяц 3, юзер 1), в каждой таблице есть CHECK CONSTRAINT, на основной таблице висит триггер на insert который проверяет есть ли такая таблица в которую надо сделать вставку, если нет, то создает ее и делает insert. Обновление примерно 1к строк для одного юзера занимает примерно 160сек(секунд), что как бы ооочень долго, я считаю. explain analyze показывает такие данные - http://explain.depesz.com/s/fnz т.е. выполняется запрос 0.115мсек(миллисекунд), если же я запускаю вставку на сервере, то по монитору вижу, что каждый такой запрос выполняется 0.1-0.2..сек(секунд). Postgresql 9.4.0,пробовал запускать на 9.3 и на 9.2 - результат такой же. Причем заметил, что если база чистая и партицированных таблиц нет, то вставка происходит намного быстрее.


А если тоже самое сделать на схеме без партиций (прямо указав с какой таблицей работаете)?
Тут есть 4 теории:

1)время планирования запроса (сколько у вас партиций сейчас)?
2)время на commit транзакции (вы все 1000 строк в одной транзакции обновляете или каждый update в своей транзакции)?
3)сетевые задержки (у вас приложение и база на одном сервере живут или на разных)?
4)диски перегруженные на запись (explain analyze никак время на commit транзакции и запись wal не учитывает).

--Maxim Boguk
www.postgresql-consulting.ru
VerusK
Дата: 26.03.2015 09:22:03 
"Append  (cost=0.00..7.35 rows=2 width=410) (actual time=0.015..0.015 rows=0 loops=1)"
"  Buffers: shared hit=2"
"  ->  Seq Scan on stats  (cost=0.00..0.00 rows=1 width=664) (actual time=0.001..0.001 rows=0 loops=1)"
"        Filter: ((ts_spawn = 1426960800) AND (user_id = 1) AND (offer_targeting_id = 132) AND (offer_id = 123) AND (traff_type = 4) AND (operator_id = 0) AND (landing_id = 0) AND (country_id = 113) AND ((subacc_1)::text = ''::text) AND ((subacc_2)::text =  (...)"
"  ->  Index Scan using stats_y2015_m3_u1_pk on stats_y2015_m3_u1  (cost=0.28..7.35 rows=1 width=155) (actual time=0.013..0.013 rows=0 loops=1)"
"        Index Cond: ((ts_spawn = 1426960800) AND (user_id = 1) AND (offer_targeting_id = 132) AND (offer_id = 123) AND (traff_type = 4) AND (operator_id = 0) AND (country_id = 113) AND ((subacc_1)::text = ''::text) AND ((subacc_2)::text = ''::text) AND ((s (...)"
"        Buffers: shared hit=2"
"Planning time: 47.748 ms"
"Execution time: 0.164 ms"


Ответ на второй пост:
Если выполнять просто на таблице:
"Update on stats_y2015_m3_u1 stats  (cost=0.28..7.42 rows=1 width=161) (actual time=0.016..0.016 rows=0 loops=1)"
"  ->  Index Scan using stats_y2015_m3_u1_pk on stats_y2015_m3_u1 stats  (cost=0.28..7.42 rows=1 width=161) (actual time=0.015..0.015 rows=0 loops=1)"
"        Index Cond: ((ts_spawn = 1426960800) AND (user_id = 1) AND (offer_targeting_id = 132) AND (offer_id = 123) AND (traffic_manager_id = 0) AND (traff_type = 4) AND (operator_id = 0) AND (country_id = 113) AND ((subacc_1)::text = ''::text) AND ((subacc (...)"
"Planning time: 0.675 ms"
"Execution time: 0.166 ms"


1. Партиций сейчас именно по таблице stats около 100
2. делаю общий commit, я засекал время его выполнения в коде, выполняется моментально
3. на разных серверах, но я же смотрю время выполнения запроса непосредственно на сервере.
4. если верить pg_activity диски вообще не используются, памяти на сервере 128Гб, вся база весит 35, пробовал отключить fsync - не помогло вообще никак.
Maxim Boguk
Дата: 26.03.2015 13:03:59
VerusK
"Append  (cost=0.00..7.35 rows=2 width=410) (actual time=0.015..0.015 rows=0 loops=1)"
"  Buffers: shared hit=2"
"  ->  Seq Scan on stats  (cost=0.00..0.00 rows=1 width=664) (actual time=0.001..0.001 rows=0 loops=1)"
"        Filter: ((ts_spawn = 1426960800) AND (user_id = 1) AND (offer_targeting_id = 132) AND (offer_id = 123) AND (traff_type = 4) AND (operator_id = 0) AND (landing_id = 0) AND (country_id = 113) AND ((subacc_1)::text = ''::text) AND ((subacc_2)::text =  (...)"
"  ->  Index Scan using stats_y2015_m3_u1_pk on stats_y2015_m3_u1  (cost=0.28..7.35 rows=1 width=155) (actual time=0.013..0.013 rows=0 loops=1)"
"        Index Cond: ((ts_spawn = 1426960800) AND (user_id = 1) AND (offer_targeting_id = 132) AND (offer_id = 123) AND (traff_type = 4) AND (operator_id = 0) AND (country_id = 113) AND ((subacc_1)::text = ''::text) AND ((subacc_2)::text = ''::text) AND ((s (...)"
"        Buffers: shared hit=2"
"Planning time: 47.748 ms"
"Execution time: 0.164 ms"


Ответ на второй пост:
Если выполнять просто на таблице:
"Update on stats_y2015_m3_u1 stats  (cost=0.28..7.42 rows=1 width=161) (actual time=0.016..0.016 rows=0 loops=1)"
"  ->  Index Scan using stats_y2015_m3_u1_pk on stats_y2015_m3_u1 stats  (cost=0.28..7.42 rows=1 width=161) (actual time=0.015..0.015 rows=0 loops=1)"
"        Index Cond: ((ts_spawn = 1426960800) AND (user_id = 1) AND (offer_targeting_id = 132) AND (offer_id = 123) AND (traffic_manager_id = 0) AND (traff_type = 4) AND (operator_id = 0) AND (country_id = 113) AND ((subacc_1)::text = ''::text) AND ((subacc (...)"
"Planning time: 0.675 ms"
"Execution time: 0.166 ms"


1. Партиций сейчас именно по таблице stats около 100
2. делаю общий commit, я засекал время его выполнения в коде, выполняется моментально
3. на разных серверах, но я же смотрю время выполнения запроса непосредственно на сервере.
4. если верить pg_activity диски вообще не используются, памяти на сервере 128Гб, вся база весит 35, пробовал отключить fsync - не помогло вообще никак.


1)это в пределах разумного
2)это хорошо
4)тоже очень хорошо...

а вот про 3 - а как собственно вы смотрите время выплнения запроса непосредственно на сервере?
попробуйте включить log_min_duration_statement=0 и прислать то что записалось в лог для одного из ваших проблемных запросов.

--Maxim Boguk
www.postgresql-consulting.ru
VerusK
Дата: 26.03.2015 13:41:42
Maxim Boguk, вот, выдернул из лога только что

015-03-26 10:16:04 UTC, LOG:  duration: 150.878 ms  statement: 
UPDATE stats SET actions=(stats.actions + 0), 
offer_clicks=(stats.offer_clicks + 0), uniq=(stats.uniq + 1), raw=(stats.raw + 0), tb_uniq=(stats.tb_uniq +0), 
tb_raw=(stats.tb_raw + 0), leads=(stats.leads + 0), subs=(stats.subs + 0), unsubs=(stats.unsubs + 0), 
rebills=(stats.rebills + 0), sales=(stats.sales + 0), 
holds=(stats.holds + 0), rejects=(stats.rejects + 0), trashes=(stats.trashes + 0), user_lead_income=(stats.user_lead_income + 0.0), 
user_subs_income=(stats.user_subs_income + 0.0), user_rebill_income=(stats.user_rebill_income + 0.0), 
user_sales_income=(stats.user_sales_income + 0.0), user_hold_income=(stats.user_hold_income + 0.0), 
system_lead_income=(stats.system_lead_income + 0.0), system_subs_income=(stats.system_subs_income + 0.0), 
system_rebill_income=(stats.system_rebill_income + 0.0), system_sales_income=(stats.system_sales_income + 0.0), 
system_hold_income=(stats.system_hold_income + 0.0) 
WHERE 
stats.ts_spawn = 1427364000 AND stats.user_id = 1 AND stats.offer_targeting_id = 124 AND stats.offer_id = 135 AND stats.traffic_manager_id = 0 AND 
stats.traff_type = 2 AND stats.operator_id = 0 AND stats.country_id = 192 AND 
stats.subacc_1 = '' AND stats.subacc_2 = '' AND stats.subacc_3 = '' AND 
stats.subacc_4 = '' AND stats.utm_source = '' AND stats.utm_medium = '' AND stats.utm_term = '' AND 
stats.utm_content = '' AND stats.utm_campaign = '' AND stats.prelanding_id = 223 AND stats.landing_id = 345 AND 
stats.platform_id = 10 AND stats.platform_out_id = 15 AND stats.os_id = 5 AND stats.browser_id = 34
Ivan Durak
Дата: 26.03.2015 15:44:58
у тебя для апдейта 1000 строк, вызывается 100 апдейтов???
нельзя пакетно?
Ivan Durak
Дата: 26.03.2015 15:47:26
Ivan Durak
у тебя для апдейта 1000 строк, вызывается 100 апдейтов???
нельзя пакетно?

в смысле всю свою статистику инсертишь в лог. А раз в N секунд из лога пакетно группируешь и обновляешь таблицы статистики,
а лог очищаешь