Часто на нашей практике у пользователей возникают жалобы, что “программа тормозит”. За долгое время поддержки, у нас сформировался большой опыт по диагностике и решению таких проблем. Речь пойдет о приложениях, написанных на открытой и бесплатной платформе lsFusion. В частности, о самом сложном решении - lsFusion ERP, на котором работают крупнейшие розничные сети Беларуси, а также розничные сети в России и Узбекистане.

За несколько лет сформировалось некоторое сообщество разработчиков на платформе lsFusion, у которых на больших объемах данных могут возникать схожие проблемы. В этой статье я опишу основные причины торможений и последовательность действий по их выявлению. Некоторые из причин актуальны только для решений на основе платформы, но многие из описанных проблем касаются любых java-приложений, работающих с PostgreSQL.

Нехватка ресурсов

Первое с чего мы начинаем проверку после обращения - это анализ текущей загрузки серверов. Если настроен Zabbix, то смотрим в нем, если нет - то через стандартную утилиту dstat. 

crontab -e

* * * * * dstat -tcdngym --fs -l -i --noheaders --nocolor 3 18 >> /var/log/dstat.log

/var/log/dstat.log {
  rotate 5
  weekly
  compress
  missingok
  notifempty
}

Если сервер приложений и СУБД установлены на разных виртуальных машинах, то проверяем ресурсы на обоих.

В нормальной ситуации Zabbix выглядит, например, вот так :

Можно говорить, что серверу достаточно ресурсов, если каждому процессу выделяется достаточно процессорного времени, памяти и дисковых операций вне зависимости от других процессов. Как только какого-то из ресурсов недостаточно, начинаются тормоза.

CPU

В нормальном режиме работы загрузка CPU не должна превышать 70-80%. Как только этот порог превышен, то образовывается своего рода “пробка”. Начинается частое переключение процессов между ядрами, что еще больше усугубляет ситуацию и снижает производительность системы. То есть при превышении нагрузки CPU на 5-10% выше порога происходит значительно большее падение скорости выполнения процессов.

В ситуации с CPU хорошо подходит аналогия с дорожным движением. Пропускная способность дороги может быть достаточна для определенной интенсивности движения. Однако, если одна машина резко затормозит, то может легко образоваться пробка за счет того, что все машины будут упираться в следующие, постоянно тормозить и разгоняться. При этом интенсивность движения не меняется, и продолжает ехать тоже самое количество автомобилей. Но пропускной способности уже недостаточно.

С загрузкой CPU похожая ситуация. Если в среднем загрузка CPU 60%, то как только какое-то временное событие приведет к повышению до 80%, то процессы будут становиться в очередь на свободные ядра, не успевать выполняться за выделенный интервал, и обратно попадать в очередь. При этом из-за торможений, пользователи за счет асинхронности программы, будут генерировать все новые и новые запросы, и в итоге из такого критического состояния сервер будет выходить очень долго (пока нагрузка не снизится ниже первоначального уровня). Чтобы избежать такой проблемы лучше всегда иметь определенный запас свободных ядер на сервере.

Также бывает полезно увеличить в операционной системе “стоимость” переключения процессов между ядрами, чтобы избежать излишней траты ресурсов. Для этого в /etc/sysctl.conf добавляются строки :

kernel.sched_migration_cost_ns = 5000000
kernel.sched_autogroup_enabled = 0

Следует также учитывать, что логическим ядрам, выделяемых виртуальной машине при включенном Hyper Threading, может соответствовать лишь половина физических ядер. Соответственно, при загрузке CPU больше 50% производительность увеличивается не линейно, а несколько ниже. Также не стоит выделять все ядра конкретного сервера виртуальной машине, а оставлять несколько для работы самого гипервизора.

Еще стоит обращать внимание на CPU system time. Он показывает, сколько времени процессы проводят в системных вызовах ядра ОС. Обычно этот показатель не превышает 3%. Высокое значение sys может свидетельствовать о разных проблемах. Например, такая ситуация может возникнуть, если на большом объеме памяти не увеличивать vm.min_free_kbytes, и может много времени тратиться на выделение памяти.

Еще одной причиной долгих системных вызовов могут быть проблемы на стороне виртуализации сервера. Как правило, мы не имеем доступа к гипервизорам, а их настройками занимаются системные администраторы клиентов. К сожалению, из-за этого часто возникают недопонимания, так как со стороны гостевой системы может быть все настроено хорошо, а доказать проблемы на стороне гипервизора достаточно затруднительно. 

Однако, в общем случае диагностика высокого времени sys - достаточно сложная задача за пределами этой статьи (но можно начать с perf top). 

Память

Во время работы приложений важно следить за наличием доступной памяти и использованием swap. Когда речь идет о сервере приложений, то памяти может не хватать как внутри java-приложения, так и физической памяти внутри операционной системы. Как смотреть за потреблением памяти внутри сервера приложений более подробно описано в этой статье. 

У сервера приложений достаточно предсказуемое потребление памяти в операционной системе (размер кучи плюс определенный процент), что позволяет достаточно легко назначать выделяемые ресурсы. А вот с СУБД ситуация несколько сложнее. PostgreSQL использует фиксированный размер памяти под общие буферы (параметр shared_buffers), но вот каждое отдельное соединение, которое создает отдельный процесс в ОС, может забирать себе дополнительную память для выполнения запросов с учетом параметров work_mem и temp_buffers. Причем оба этих параметра ограничивают по памяти лишь определенную часть выполняемых запросов. Соответственно, каждый процесс может потреблять значительно больше этих лимитов в зависимости от сложности запросов. Учитывая все это, память потребляемая СУБД может сильно варьироваться в зависимости от нагрузки (количества пользователей и сложностей запросов), и иногда даже уходить в своп. Принцип изменения параметров в данном случае следующий : понижение work_mem и temp_buffers уменьшает потребление памяти каждым процессом, что уменьшает дисперсию использования памяти. Уменьшение shared_buffers снизит статическое потребление, но увеличит нагрузку на диск.

Диск

Ключевым фактором влияющим на скорость работы дисков является использование SSD на серверах базы данных. Без SSD можно забыть про быструю работу диска и приложений на больших объемах. Однако, диск важен исключительно для СУБД, а сервер приложений его практически не использует.

Два основных показателя работы диска, за которыми следует следить - это очередь диска и время, которое процессор проводит в режиме ожидания IO (CPU iowait time). Очередь диска (avgqu_sz) можно смотреть или через Zabbix, или через утилиту iostat с параметром -x. Наличие очереди свидетельствует о том, что процессы ожидают получения данных, и пропускной способности (throughput) диска не хватает. Высокое время ожидания процессором может быть как из-за очереди диска, так и из-за долгого времени отклика (latency). Такое может происходить, если, например, СХД с дисками подключена через медленное сетевое подключение. Чтобы уменьшить время отклика можно подключить диски напрямую к серверу по более быстрому интерфейсу.

Таким образом, в случае проблем с диском всегда будет высокий cpu iowait. Если при этом высокая очередь диска, то не хватает пропускной способности. В противном случае, это означает, что просто диск отдает данные с высокой задержкой. В редких случаях высокий iowait time может быть вызван обращением к каким-то другим устройствам ввода/вывода (например, из-за сетевых проблем).

В случае наличия проблем с диском, существуют два основных способа решения. Первый - это ускорять работу дисков за счет использования более быстрых NVMe дисков или подключения их по более быстрому интерфейсу. Второй - это наращивать память на сервере, за счет чего можно увеличивать параметры shared_buffers, work_mem и temp_buffers, что приведет к более интенсивному использованию памяти вместо диска. Также, в PostgreSQL можно перенести все временные файлы и таблицы в отдельный workspace на отдельном диске, которые подключен по другому интерфейсу. В таком случае, интенсивная работа с временными файлами, которая обычно осуществляется конкретными “тяжелыми” SQL-запросами, не будет блокировать обращение к основным таблицам базы данных. Таким же образом можно вынести каталог pg_wal с WAL-файлами на отдельный диск.

Неоптимальный код

Сразу оговорюсь, что не существует максимально быстрого кода. Всегда существует возможность оптимизации. Однако, в случае с оптимизацией, обычно работает правило Парето : с 20% усилиями можно получить 80% оптимизации. А вот дальнейшая оптимизация требует значительно больше времени и дает все меньший результат. Когда разработчиком реализуется определенная задача, то можно сделать быстро, но не оптимально. И часто именно так экономически выгоднее. Пользователю будет не принципиально, если отчет, который он формирует раз в месяц будет выполняться 10 секунд вместо одной, а разница в затратах времени разработчика может отличаться в разы. Но бывает и наоборот : есть смысл потратить десять часов на оптимизацию, что уменьшить время выполнения частого действия в два раза.

Непосредственно у нас в компании на внутреннем языке lsFusion пишут десятки разработчиков. К сожалению, не все всегда знают и учитывают специфику работы lsFusion, а также планы выполнения SQL запросов в PostgreSQL. Есть и такие, кто вообще не задумывается о том, как это будет в дальнейшем выполняться. В подавляющем большинстве случаев платформа lsFusion генерирует достаточно эффективные запросы, которые будут выполняться относительно быстро. Однако, в определенных ситуациях могут быть проблемы, и тогда в работу включаются люди, которые более глубоко разбираются в теме. В частности, они умеют анализировать планы выполнений SQL запросов и лучше разбираются в механизме генерации запросов платформой.

Любое действие требует выполнение определенного алгоритма, у которого есть какая-то сложность. Есть концепция, в которой сложность условно можно разделить на два типа : необходимая (essential) и случайная (accidental). Первая обусловлена самой задачей, а вторая - неэффективным подходом к ее решению. Например, если нужно сделать отчет с суммой продаж по группам за год, то невозможно обойтись без того, чтобы считать все продажи за день по индексу и посчитать сумму по каждой строке. Это необходимая сложность. Однако, если вместо этого, чтобы посчитать сумму, алгоритм получает данные за все время, а потом фильтрует по дате, то сложность будет в разы больше. И это уже будет случайная сложность. Суть оптимизации всегда в том, чтобы избавиться от случайной сложности, но никогда невозможно сделать быстрее, чем требует необходимая сложность.

Монитор процессов

Каждое неоптимальное действие приводит не только к торможению у конкретного пользователя, который его выполняет, но и к повышенному потреблению ресурсов всего сервера. Таким образом, в случае недостатка ресурсов нужно либо увеличивать их количество, или искать процессы, оптимизировав которые можно значительно сократить потребление ресурсов. Для этой цели в платформе lsFusion есть специальная форма Монитор процессов из системного модуля ProcessMonitor. С ее помощью можно следить за текущими выполняющимися процессами, находя тем самым долгие или частые действия.

Каждая строка в таблице - это отдельный поток, который в данный момент выполняется на сервере. Если действие не асинхронное, то пользователь в данный момент “висит”. Соответственно, при жалобе именно на зависание, а не торможение, в первую очередь мы идем в Монитор процессов. В любой момент времени поток или выполняет какой-то Java-код (выделяется светло голубым цветом) или ждет завершения SQL-запроса.

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

Описание основных колонок :

• Компьютер/Пользователь. IP-адрес/имя компьютера и логин, под которым пользователь зашел в систему.

• Время начала вызова. Время, когда на сервер был получен запрос, и клиент начал ожидать его завершения (фактически завис).

• Время запуска (SQL). Время запуска SQL-запроса, если процесс сейчас ожидает его выполнения.

• Время начала транзакции (SQL). Время, когда была начата транзакция в базе данных. Транзакция начинается в каждом случае сохранения изменения в базу данных (чтобы изменения применились только все одновременно). Если значение пустое, то значит SQL-запрос выполняется не в транзакции.

• Запрос (SQL). Урезанный текст SQL запроса. Полный можно получить, нажав кнопку в колонке Копировать полный запрос.

• ID процесса (SQL). Внутренний идентификатор процесса в PostgreSQL.

• Имя java-потока. Внутреннее название java-потока, который сейчас выполняется. По нему можно определить идентификатор формы, из которой пользователь вызвал действие. Но также может указывать на потоки планировщика, обработки http-запросов и т.д.

• Выделенная память/Память за последний интервал. Показывает сколько памяти внутри сервера приложений было использовано данным потоком за все время и за последние полторы минуты (настраивается). Позволяет легко найти потоки, потребляющие много памяти.

• След java-потока/Блокировка/Статус. В ней содержится весь текущий java stacktrace, и в каком статусе находится java-процесс (возможно кем-то заблокирован).

• LSF след потока. Показывает текущий стек вызовов действий внутри кода на внутреннем языке lsFusion с указанием модулей и номеров строк (по схожему принципу, как и java stacktrace) Если внутри стэка вызовов встречается оператор FOR, то показывает сколько всего элементов во множестве, и какой элемент по номеру сейчас обрабатывается.

• Debug info. Содержит разную дополнительную информацию полезную для диагностики. В частности, там могут содержаться внутренние идентификаторы конкретных объектов, которые используются в действиях из стэка, а также количество записей во временных таблицах, если такие имеются.

Обычно, когда мы видим, что сервер СУБД перегружен, и какого-то ресурса недостаточно (как правило, CPU или диска), то мы сразу заходим в Монитор процессов и сортируем по колонке Время запуска (SQL). Вверху будут все процессы, в которых долго выполняется SQL-запрос, и, скорее всего, они являются главными потребителями дефицитных ресурсов. Дальше по LSF-стеку и другим колонкам легко определяется какие именно действия выполняются, и кто их запустил. Наилучшими кандидатами на оптимизацию являются те, которые либо запустились очень давно, либо те, где много процессов с одинаковым стэком. В конце концов, на основе LSF-стэка анализируется исходный код медленных действий и делаются соответствующие оптимизации : рефакторинг кода, добавление индексов, добавление материализаций и прочее.

Логирование медленных запросов

Если же всем серверам достаточно ресурсов, и сборка мусора также в порядке, но при этом есть жалобы конкретных пользователей, то значит проблема в каких-то определенных процессах. При этом их не всегда можно “словить” в Мониторе процессов, так как запросы могут выполняться медленно только в определенных случаях.

В таких случаях на уровне платформы существует механизм, который позволяет логировать все запросы, выполняющиеся дольше определенного порога. Чтобы включить его для конкретных пользователей нужно зайти в форму Администрирование / Система / Настройки / Логирования и выставить две первые галочки для нужных пользователей.

Первая опция включает логирование SQL-запросов, которые выполняются дольше, чем порог в миллисекундах, заданный в Администрирование / Система / Настройки / Параметры / explainThreshold. К сожалению, в PostgreSQL нельзя получить план выполнения для уже выполнившегося запроса, который был запущено без EXPLAIN ANALYZE. По этой причине механизм логирования просто отменяет запрос, который выполняется дольше порога, а затем запускает его же с EXPLAIN ANALYZE. Это создает дополнительную нагрузку на сервер, и увеличивает время выполнения таких запросов. По этой причине включать логирование стоит только на время диагностики проблемы, а потом выключать.

Логи будут записываться в файл logs/explain.log. В нем будут сохранены текст SQL запроса, его актуальный план выполнения (вывод EXPLAIN ANALYZE), LSF stack и debug info. Обычно этого достаточно для того, чтобы определить, что именно и зачем делал этот запрос.

EXPLAIN (ANALYZE, VERBOSE, BUFFERS, COSTS) INSERT INTO t_5032 (k0,p00) (SELECT t0.key0 AS jkey0,t2.e0 AS jprop0 FROM Sale_invoiceDetail t0 JOIN (SELECT k0 AS k0,k1 AS k1,k2 AS k2,p00 AS e0 FROM t_5047) t1 ON t1.k0=t0.Sale_sku_InvoiceDetail AND t1.k1=t0.Sale_supplierStock_InvoiceDetail AND t1.k2=t0.Sale_dateTime_InvoiceDetail LEFT JOIN Sale_invoice ...
LSF stack:
	Чтение изменений формы : FORM[1193790517 - Sale.userInvoice,RN[clientAddress: 192.168.30.43,5005599303 - Employee.Employee 'Сотрудник',927444570,SQL@42212139]]
	Выполнение локальных событий
	Локальное событие : DS@563607015,p222283 [SaleFullPrice(202:1)]
	Выполнение действия : p222283 [SaleFullPrice(202:1)]
	Материализация изменений свойств : p223819
	Обращение к SQL : INSERT INTO t_5032 (k0,p00) (SELECT t0.key0 AS jkey0,t2.e0 AS jprop0 FROM Sale_invoiceDetail t0 JOIN w0jdfkjsd0ref t1 ON t1.k0=t0.Sale_sku_InvoiceDetail AND t1.k1=t0.Sale_supplierStock_InvoiceDetail AND t1.k2=t0.Sale_dateTime_InvoiceDetail LEFT JOIN Sale_invoice t3 ON t3.key0=t0.Sale_invoice_InvoiceDetail LEFT JOIN w0jdfkjsd1ref ...
Params debug info: 
	15725112021 - Sale.UserInvoice 'Накладная (польз.) (продажа)'
	13:13 - TIME 'Время'
t Insert on pg_temp_449.t_5032  (cost=8.97..9.10 rows=2 width=16) (actual time=13847.747..13847.756 rows=0 loops=1)
    Buffers: shared hit=4086 read=76416 dirtied=2, local hit=5 read=1 dirtied=3 written=2
t   ->  Subquery Scan on "*SELECT*"  (cost=8.97..9.10 rows=2 width=16) (actual time=13847.614..13847.626 rows=1 loops=1)
          Output: "*SELECT*".jprop0, "*SELECT*".jkey0
          Buffers: shared hit=4086 read=76416 dirtied=2, local hit=4
t         ->  Unique  (cost=8.97..9.00 rows=2 width=16) (actual time=13847.611..13847.623 rows=1 loops=1)
                Output: t0.key0, t_5048.p00
                Buffers: shared hit=4086 read=76416 dirtied=2, local hit=4
t               ->  Sort  (cost=8.97..8.98 rows=2 width=16) (actual time=13847.609..13847.618 rows=2 loops=1)
                      Output: t0.key0, t_5048.p00
                      Sort Key: t0.key0, t_5048.p00
                      Sort Method: quicksort  Memory: 25kB
                      Buffers: shared hit=4086 read=76416 dirtied=2, local hit=4
t                     ->  Append  (cost=2.24..8.95 rows=2 width=16) (actual time=0.038..13847.611 rows=2 loops=1)
                            Buffers: shared hit=4086 read=76416 dirtied=2, local hit=4
                            ->  Nested Loop Left Join  (cost=2.24..3.57 rows=1 width=16) (actual time=0.038..0.044 rows=1 loops=1)
                                  Output: t0.key0, t_5048.p00
                                  Inner Unique: true
                                  Join Filter: (t_5048.k2 = (to_timestamp((((t3.sale_date_invoice)::character(10))::text || '13:13:00'::text), 'YYYY-MM-DDHH24:MI:SS.MS'::text))::timestamp without time zone)
                                  Buffers: shared hit=9, local hit=3
                                  ->  Nested Loop Left Join  (cost=1.98..3.10 rows=1 width=28) (actual time=0.025..0.029 rows=1 loops=1)
                                        Output: t0.key0, t0.sale_sku_invoicedetail, t0.sale_supplierstock_invoicedetail, t3.sale_date_invoice
                                        Inner Unique: true
                                        Join Filter: (t3.key0 = t0.sale_invoice_invoicedetail)
                                        Buffers: shared hit=9, local hit=1
                                        ->  Nested Loop  (cost=1.12..1.90 rows=1 width=32) (actual time=0.017..0.020 rows=1 loops=1)
                                              Output: t0.key0, t0.sale_sku_invoicedetail, t0.sale_supplierstock_invoicedetail, t0.sale_invoice_invoicedetail
                                              Buffers: shared hit=5, local hit=1
                                              ->  Seq Scan on pg_temp_449.t_5047  (cost=0.00..0.40 rows=1 width=24) (actual time=0.004..0.004 rows=1 loops=1)
                                                    Output: t_5047.k2, t_5047.k0, t_5047.k1, t_5047.p00
                                                    Filter: (t_5047.p00 IS NOT NULL)
                                                    Rows Removed by Filter: 5
                                                    Buffers: local hit=1
                                              ->  Index Scan using sale_sku_invoicedetail_sale_datetime_invoicedetail_idx_sale_inv on public.sale_invoicedetail t0  (cost=1.12..1.45 rows=1 width=40) (actual time=0.012..0.013 rows=1 loops=1)
                                                    Output: t0.key0, t0.sale_sku_invoicedetail, t0.sale_supplierstock_invoicedetail, t0.sale_datetime_invoicedetail, t0.sale_invoice_invoicedetail
                                                    Index Cond: ((t0.sale_sku_invoicedetail = t_5047.k0) AND (t0.sale_datetime_invoicedetail = t_5047.k2))
                                                    Filter: ((t0.sale_invoice_invoicedetail = '15725112021'::bigint) AND (t_5047.k1 = t0.sale_supplierstock_invoicedetail))
                                                    Buffers: shared hit=5
                                        ->  Index Scan using sale_invoice_pkey on public.sale_invoice t3  (cost=0.85..1.15 rows=1 width=12) (actual time=0.007..0.007 rows=1 loops=1)
                                              Output: t3.key0, t3.salepurchaseinvoice_createpurchaseinvoice_invoice, t3.salepurchaseinvoice_purchaseinvoice_invoice, ...
                                              Index Cond: (t3.key0 = '15725112021'::bigint)
                                              Buffers: shared hit=4
                                  ->  Index Scan using t_5048_pkey on pg_temp_449.t_5048  (cost=0.27..0.38 rows=1 width=32) (actual time=0.002..0.002 rows=1 loops=1)
                                        Output: t_5048.k2, t_5048.k0, t_5048.k1, t_5048.p00
                                        Index Cond: ((t_5048.k0 = t0.sale_sku_invoicedetail) AND (t_5048.k1 = t0.sale_supplierstock_invoicedetail))
                                        Buffers: local hit=2
t                           ->  Nested Loop  (cost=1.73..5.23 rows=1 width=16) (actual time=13810.542..13847.563 rows=1 loops=1)
                                  Output: t0_1.key0, t_5048_1.p00
                                  Inner Unique: true
                                  Join Filter: (t_5048_1.k2 = (to_timestamp((((t1.sale_date_invoice)::character(10))::text || '13:13:00'::text), 'YYYY-MM-DDHH24:MI:SS.MS'::text))::timestamp without time zone)
                                  Buffers: shared hit=4077 read=76416 dirtied=2, local hit=1
t                                 ->  Nested Loop  (cost=0.88..3.98 rows=1 width=32) (actual time=13810.509..13847.527 rows=1 loops=1)
                                        Output: t0_1.key0, t0_1.sale_invoice_invoicedetail, t_5048_1.p00, t_5048_1.k2
                                        Buffers: shared hit=4073 read=76416 dirtied=2, local hit=1
                                        ->  Seq Scan on pg_temp_449.t_5048 t_5048_1  (cost=0.00..0.40 rows=1 width=32) (actual time=0.001..0.005 rows=1 loops=1)
                                              Output: t_5048_1.k2, t_5048_1.k0, t_5048_1.k1, t_5048_1.p00
                                              Filter: (t_5048_1.p00 IS NOT NULL)
                                              Rows Removed by Filter: 5
                                              Buffers: local hit=1
t                                       ->  Index Scan using sale_supplierstock_invoicedetail_sale_sku_invoicedetail_idx_sal on public.sale_invoicedetail t0_1  (cost=0.88..3.53 rows=1 width=32) (actual time=13810.505..13847.518 rows=1 loops=1)
                                              Output: t0_1.key0, t0_1.sale_invoice_invoicedetail, t0_1.sale_sku_invoicedetail, t0_1.sale_supplierstock_invoicedetail
                                              Index Cond: ((t0_1.sale_supplierstock_invoicedetail = t_5048_1.k1) AND (t0_1.sale_sku_invoicedetail = t_5048_1.k0))
                                              Filter: (t0_1.sale_invoice_invoicedetail = '15725112021'::bigint)
                                              Rows Removed by Filter: 83497
                                              Buffers: shared hit=4073 read=76416 dirtied=2
                                  ->  Index Scan using sale_invoice_pkey on public.sale_invoice t1  (cost=0.85..1.15 rows=1 width=12) (actual time=0.017..0.017 rows=1 loops=1)
                                        Output: t1.key0, t1.salepurchaseinvoice_createpurchaseinvoice_invoice, t1.salepurchaseinvoice_purchaseinvoice_invoice, ...
                                          Index Cond: (t1.key0 = '15725112021'::bigint)
                                         Buffers: shared hit=4
   Planning:
     Buffers: shared hit=97, local hit=34
   Planning Time: 1.256 ms
   Execution Time: 13847.881 ms

Вторая колонка в настройках на скрине выше включает логирование выполнения долгих запросов уже на стороне сервера приложений. При включенной опции в файл logs/explainapp.log записывается информация о конкретных действиях, время работы которых превысило параметр explainAppThreshold. Для каждого запроса в лог будет записано дерево вызовов действий lsfusion с указанием модуля и строки кода, а также накопленное время выполнения на сервере приложений и на SQL-сервере.

13 июн. 2023 14:12:37,047 Ольга Сергей - User-ЏЉ - 10.9.3.5  INFO ExplainAppLogger -  (app: !! 2314 !!, sql: 2119, sql/app ratio: 47%, allocated app: 0 B, cache hit ratio - precompile: --% (-11006); compile: --% (-3326); lazy: --% (-166335); other: --% (-68) [J: --% (-18); DC: --% (-39); E: --% (-2571); JE: --% (-82); IC: --% (-242); RS: --% (0); AH: --% (0); Q: --% (-374); TT: --% (-68); TL: --% (-9192); UC: --% (-10513); HP: --% (-493); PL: --% (-86); PN: --% (-83); IL: --% (-150537); QL: --% (-37); NL: --% (-6400)])
Чтение изменений формы : FORM[377642325 - Purchase.userInvoice,RN[clientAddress: 10.9.3.5,215904798 - Employee.Employee 'Сотрудник',559496833,SQL@34907890]] (app: !! 2314 !!, sql: 2119, sql/app ratio: 47%, allocated app: 0 B, cache hit ratio - precompile: --% (-11006); compile: --% (-3326); lazy: --% (-166335); other: --% (-68) [J: --% (-18); DC: --% (-39); E: --% (-2571); JE: --% (-82); IC: --% (-242); RS: --% (0); AH: --% (0); Q: --% (-374); TT: --% (-68); TL: --% (-9192); UC: --% (-10513); HP: --% (-493); PL: --% (-86); PN: --% (-83); IL: --% (-150537); QL: --% (-37); NL: --% (-6400)])
	Определение изменившихся значений свойств (app: !! 324 !!, sql: 790, sql/app ratio: 70%, allocated app: 0 B, cache hit ratio - precompile: 100% (934); compile: 100% (240); lazy: 93% (11056); other: 100% (14) [J: --% (0); DC: --% (0); E: 100% (220); JE: --% (0); IC: 100% (14); RS: --% (0); AH: --% (0); Q: 100% (6); TT: 100% (14); TL: 62% (274); UC: 100% (929); HP: 100% (5); PL: --% (0); PN: --% (0); IL: 94% (10326); QL: --% (0); NL: 83% (456)])
		Чтение значений изменившихся свойств : Purchase.shipmentSum[Purchase.UserInvoiceDetail] 'Сумма (учетная)' [PurchaseShipment(2497:49↕)],Purchase.invoicePrice[Purchase.UserInvoiceDetail] 'Цена с НДС' [PurchaseInvoice(1036:33↕)],Purchase.price[Purchase.UserInvoiceDetail] 'Цена' [PurchaseInvoice(947:20↕)],Purchase.manufacturingSum[Purchase.UserInvoiceDetail] 'Сумма изготовителя' [PurchaseManufacturingPrice(453:57↕)],Purchase.invoiceSum[Purchase.UserInvoiceDetail] 'Сумма с НДС' [PurchaseInvoice(1187:52↕)],Purchase.shipmentPrice[Purchase.UserInvoiceDetail] 'Цена (учетная)' [PurchaseShipment(2464:50↕)],Purchase.sum[Purchase.UserInvoiceDetail] 'Сумма' [PurchaseInvoice(1170:19↕)],Purchase.manufacturingMarkup[Purchase.UserInvoiceDetail] 'Надбавка,% (к цене изготовителя)' [PurchaseManufacturingPrice(322:69↕)],Purchase.VATSum[Purchase.UserInvoiceDetail] 'Сумма НДС' [PurchaseInvoice(1186:46↕)] (app: !! 220 !!, sql: 335, sql/app ratio: 60%, allocated app: 0 B, cache hit ratio - precompile: 100% (358); compile: 100% (95); lazy: 82% (1931); other: 100% (10) [J: --% (0); DC: --% (0); E: 100% (82); JE: --% (0); IC: 100% (10); RS: --% (0); AH: --% (0); Q: 100% (3); TT: 100% (10); TL: 62% (198); UC: 100% (356); HP: 100% (2); PL: --% (0); PN: --% (0); IL: 85% (1534); QL: --% (0); NL: 79% (199)])
	Выполнение локальных событий (app: !! 1984 !!, sql: 1329, sql/app ratio: 40%, allocated app: 0 B, cache hit ratio - precompile: --% (-11944); compile: --% (-3566); lazy: --% (-177603); other: --% (-82) [J: --% (-18); DC: --% (-39); E: --% (-2791); JE: --% (-82); IC: --% (-256); RS: --% (0); AH: --% (0); Q: --% (-380); TT: --% (-82); TL: --% (-9548); UC: --% (-11446); HP: --% (-498); PL: --% (-86); PN: --% (-83); IL: --% (-160993); QL: --% (-37); NL: --% (-6856)])
		Локальное событие : DS@710294688,p241022 [PricingPurchase(199:1)] (app: !! 313 !!, sql: 140, sql/app ratio: 30%, allocated app: 0 B, cache hit ratio - precompile: 100% (544); compile: 98% (104); lazy: 84% (2277); other: 100% (6) [J: --% (0); DC: 100% (1); E: 100% (92); JE: 33% (3); IC: 100% (5); RS: --% (0); AH: --% (0); Q: 100% (3); TT: 100% (6); TL: 65% (172); UC: 100% (484); HP: 100% (60); PL: --% (0); PN: --% (0); IL: 85% (1896); QL: --% (0); NL: 83% (209)])
			Выполнение действия : p241022 [PricingPurchase(199:1)] (app: !! 313 !!, sql: 140, sql/app ratio: 30%, allocated app: 0 B, cache hit ratio - precompile: 100% (544); compile: 98% (104); lazy: 84% (2274); other: 100% (6) [J: --% (0); DC: 100% (1); E: 100% (92); JE: 33% (3); IC: 100% (5); RS: --% (0); AH: --% (0); Q: 100% (3); TT: 100% (6); TL: 65% (172); UC: 100% (484); HP: 100% (60); PL: --% (0); PN: --% (0); IL: 85% (1893); QL: --% (0); NL: 83% (209)])
				Выполнение действия : p644890 'Compiled - p241022 [PricingPurchase(199:1)]' (app: !! 313 !!, sql: 140, sql/app ratio: 30%, allocated app: 0 B, cache hit ratio - precompile: 100% (544); compile: 98% (104); lazy: 84% (2272); other: 100% (6) [J: --% (0); DC: 100% (1); E: 100% (92); JE: 33% (3); IC: 100% (5); RS: --% (0); AH: --% (0); Q: 100% (3); TT: 100% (6); TL: 65% (172); UC: 100% (484); HP: 100% (60); PL: --% (0); PN: --% (0); IL: 85% (1891); QL: --% (0); NL: 83% (209)])
					Материализация изменений свойств : Purchase.pricingPrice[Purchase.UserInvoiceDetail] 'Цена входная' [PricingPurchase(144:62↕)] (app: !! 252 !!, sql: 4, sql/app ratio: 1%, allocated app: 0 B, cache hit ratio - precompile: 100% (1); compile: 100% (1); lazy: 76% (25); other: 100% (1) [J: --% (0); DC: --% (0); E: --% (0); JE: --% (0); IC: 100% (1); RS: --% (0); AH: --% (0); Q: --% (0); TT: 100% (1); TL: 63% (11); UC: 100% (1); HP: --% (0); PL: --% (0); PN: --% (0); IL: 83% (12); QL: --% (0); NL: 100% (2)])
		Локальное событие : DS@710294688,p217752 [PurchaseManufacturingPrice(185:28)] (app: !! 807 !!, sql: 339, sql/app ratio: 29%, allocated app: 0 B, cache hit ratio - precompile: 100% (574); compile: 93% (166); lazy: 81% (3151); other: 100% (7) [J: --% (0); DC: 100% (1); E: 96% (109); JE: 0% (3); IC: 96% (30); RS: --% (0); AH: --% (0); Q: 91% (23); TT: 100% (7); TL: 82% (567); UC: 100% (542); HP: 100% (32); PL: --% (0); PN: --% (0); IL: 82% (2242); QL: 50% (2); NL: 77% (340)])
			Выполнение действия : p217752 [PurchaseManufacturingPrice(185:28)] (app: !! 807 !!, sql: 339, sql/app ratio: 29%, allocated app: 0 B, cache hit ratio - precompile: 100% (574); compile: 93% (166); lazy: 81% (3148); other: 100% (7) [J: --% (0); DC: 100% (1); E: 96% (109); JE: 0% (3); IC: 96% (30); RS: --% (0); AH: --% (0); Q: 91% (23); TT: 100% (7); TL: 82% (567); UC: 100% (542); HP: 100% (32); PL: --% (0); PN: --% (0); IL: 82% (2239); QL: 50% (2); NL: 77% (340)])
				Выполнение действия : p217748 [PurchaseManufacturingPrice(186:5)] (app: !! 807 !!, sql: 339, sql/app ratio: 29%, allocated app: 0 B, cache hit ratio - precompile: 100% (574); compile: 93% (166); lazy: 81% (3146); other: 100% (7) [J: --% (0); DC: 100% (1); E: 96% (109); JE: 0% (3); IC: 96% (30); RS: --% (0); AH: --% (0); Q: 91% (23); TT: 100% (7); TL: 82% (567); UC: 100% (542); HP: 100% (32); PL: --% (0); PN: --% (0); IL: 82% (2237); QL: 50% (2); NL: 77% (340)])
						Выполнение действия : p217741 [PurchaseManufacturingPrice(187:91)] (app: !! 619 !!, sql: 260, sql/app ratio: 29%, allocated app: 0 B, cache hit ratio - precompile: 100% (390); compile: 98% (110); lazy: 81% (1741); other: 100% (6) [J: --% (0); DC: 100% (1); E: 100% (71); JE: 0% (2); IC: 100% (20); RS: --% (0); AH: --% (0); Q: 100% (16); TT: 100% (6); TL: 62% (61); UC: 100% (362); HP: 100% (28); PL: --% (0); PN: --% (0); IL: 82% (1448); QL: --% (0); NL: 77% (232)])
							Выполнение действия : p217740 [PurchaseManufacturingPrice(189:9)] (app: !! 619 !!, sql: 260, sql/app ratio: 29%, allocated app: 0 B, cache hit ratio - precompile: 100% (390); compile: 98% (110); lazy: 81% (1739); other: 100% (6) [J: --% (0); DC: 100% (1); E: 100% (71); JE: 0% (2); IC: 100% (20); RS: --% (0); AH: --% (0); Q: 100% (16); TT: 100% (6); TL: 62% (61); UC: 100% (362); HP: 100% (28); PL: --% (0); PN: --% (0); IL: 82% (1446); QL: --% (0); NL: 77% (232)])
								Выполнение действия : Purchase.updateManufacturingPrice[Purchase.UserInvoiceDetail] 'updateManufacturingPrice' [PurchaseManufacturingPrice(167:48)] (app: !! 619 !!, sql: 260, sql/app ratio: 29%, allocated app: 0 B, cache hit ratio - precompile: 100% (390); compile: 98% (110); lazy: 81% (1737); other: 100% (6) [J: --% (0); DC: 100% (1); E: 100% (71); JE: 0% (2); IC: 100% (20); RS: --% (0); AH: --% (0); Q: 100% (16); TT: 100% (6); TL: 62% (61); UC: 100% (362); HP: 100% (28); PL: --% (0); PN: --% (0); IL: 82% (1444); QL: --% (0); NL: 77% (232)])
									Выполнение действия : at updateManufacturingPrice [PurchaseManufacturingPrice(168:5)] (app: !! 619 !!, sql: 260, sql/app ratio: 29%, allocated app: 0 B, cache hit ratio - precompile: 100% (390); compile: 98% (110); lazy: 81% (1735); other: 100% (6) [J: --% (0); DC: 100% (1); E: 100% (71); JE: 0% (2); IC: 100% (20); RS: --% (0); AH: --% (0); Q: 100% (16); TT: 100% (6); TL: 62% (61); UC: 100% (362); HP: 100% (28); PL: --% (0); PN: --% (0); IL: 82% (1442); QL: --% (0); NL: 77% (232)])
										Выполнение действия : at updateManufacturingPrice [PurchaseManufacturingPrice(169:49)] (app: !! 613 !!, sql: 242, sql/app ratio: 28%, allocated app: 0 B, cache hit ratio - precompile: 100% (346); compile: 97% (93); lazy: 81% (1525); other: 100% (6) [J: --% (0); DC: 100% (1); E: 100% (59); JE: 0% (2); IC: 100% (20); RS: --% (0); AH: --% (0); Q: 100% (11); TT: 100% (6); TL: 62% (61); UC: 100% (320); HP: 100% (26); PL: --% (0); PN: --% (0); IL: 82% (1269); QL: --% (0); NL: 77% (195)])

Обычно вышеописанных логов бывает достаточно, чтобы определить виновника, и провести нужные оптимизации.

Блокировки

Еще одной возможной причиной проблемы, когда пользователи начинают зависать, является deadlock и update conflict. Сохранение любых изменений в платформе lsFusion идет в одной транзакции. На протяжении ее могут обновляться десятки таблиц и сотни разных полей. Если при этом два пользователя одновременно применяют транзакции, в которых вносятся изменения в одну и ту же запись, то последнему пользователю при попытке записи от СУБД придет ошибка 40001 (конфликт) или 40P01 (дедлок). После этого платформа автоматически перезапустит его транзакцию с самого начала. Пользователь при этом не знает о возникновении конфликта и думает, что программа просто долго сохраняет (только все бегунки перейдут в самое начало). Однако, нет никакой гарантии, что он через какое-то время опять не получит такую же ошибку повторно, и все пойдет заново.

Увидеть эту ситуацию легко в Мониторе Процессов. Там будет много процессов, у которых в колонке Номер попытки (SQL) будут значения вроде 3(cn) 2(dd), что означает у этого процесса было уже три update conflict и два deadlock.

Также информация о конфликтах и дэдлоках записывается в файл logs/sqlconflict.log.

Существует несколько способов борьбы с вышеописанными проблемами. Первый - сокращать время транзакций за счет оптимизаций логики и запросов. Чем быстрее запросы и их меньше, тем быстрее транзакция, тем меньше вероятность того, что несколько пользователей одновременно затронут одну и ту же запись. 

Второй способ - стараться избегать таких материализованных свойств, которые могут менять сразу много пользователей. Например, в розничной сети магазинов нельзя делать материализацию на общий остаток по sku для всех складов. Это приведет к тому, что все пользователи со всех магазинов (а их тысячи) будут менять одно и то же поле при одновременном проведении документов по определенному sku. При этом, материализация остатка по паре sku и складу безопасна, так как ее одновременно менять могут только несколько пользователей из одного магазина.

Длинные транзакции

Во время работы приложения очень важно следить за тем, чтобы не было длинных транзакций. PostgreSQL использует модель MVCC. Блокировки MVCC, полученные для чтения данных, не конфликтуют с блокировками, полученными для записи, и поэтому чтение никогда не мешает записи, а запись чтению. Однако, у такого подхода есть и обратная сторона : удалять старые данные можно только в тот момент, когда их уже никто не использует. То есть, когда нет ни одной транзакции старше сделанных изменений. Такая процедура очистки старых данных называется vacuum. Соответственно, если у вас “зависла” по какой-то причине транзакция, то таблицы начинают разрастаться, что увеличивает их размер и замедляет обращение к ним. Это приводит к общему торможение СУБД, а в последствии и к жалобам пользователей.

К сожалению, причины длинных транзакций могут быть совершенно разные. Например, это может быть неправильно спланированный запрос, который никогда не выполнится, так как у него сложность - миллиарды. Или долгий бэкап, который также создает транзакцию. Или внезапное уничтожение java-потока, который начал транзакцию и не успел ее закончить (хотя это можно решить через параметр idle_in_transaction_session_timeout в настройках PostgreSQL).

Для своевременного оповещения о том, что какая-то транзакция выполняется, например, больше часа мы обычно во внутренний планировщик вешаем следующее задание :

IF subtractSeconds(currentDateTime(), 3600) >= 
   [ FORMULA DATETIME '(SELECT MIN(xact_start) FROM pg_stat_activity WHERE state != \'idle\' AND NOT query LIKE \'COPY %\' AND NOT query LIKE \'% WITH ORDINALITY AS perm%\' AND $1=$1)'](10) THEN 
    EMAIL
        SUBJECT 'Длинная транзакция ' + [ FORMULA DATETIME '(SELECT MIN(xact_start) FROM pg_stat_activity WHERE state != \'idle\' AND $1=$1)'](10)
        TO 'support@gmail.com,support@yandex.ru';

Как только приходит письмо, идем в Монитор процессов, смотрим зависший процесс, и, при необходимости, там же его и отменяем через кнопку Снять процесс.

Резюме

Если подытожить все написанное выше, то последовательность нашей реакции на жалобы, связанные с производительностью следующая :

1. Проверяем переполнение ресурсов процессора и дисков. Мониторим использования свопа.

2. Анализируем логи работы сборки мусора сервера приложений.

3. Заходим в форму Монитор процессов и смотрим долгие и подозрительные процессы.

4. Включаем логирование для нескольких пользователей. Затем анализируем одновременно логи, скриншоты и показания пользователей.

5. Оптимизируем, где возможно, логику приложения. Если сложность необходимая, то либо просим клиента увеличивать ресурсы, или упрощаем логику.