refal-5-lambda icon indicating copy to clipboard operation
refal-5-lambda copied to clipboard

Тестирование, рефакторинги, оптимизации и исправления после ВКР

Open Mazdaywik opened this issue 3 years ago • 34 comments

Только что завершились две выпускные квалификационные работы:

  • @Apakhov, реализовавший построение ациклического графа суперкомпиляции путём задержки рекурсивных вызовов (#340),
  • @VladisP, реализовавший #322 и #251.

Эти расширения станут основным новшеством версии 3.4. Однако, прямо сейчас создавать новую версию преждевременно по следующим причинам.

  1. @Apakhov и @VladisP намеренно работали с очень ограниченным объёмом кода (в смысле, я ограничил их работу). Работа @Apakhov’а была ограничена файлом OptTree-Drive-Expr.ref, работа @VladisP’а — файлами GenericMatch.ref и OptTree-Spec.ref. Однако, полноценная реализация новых функций требует изменения куда большего объёма кода (например, скрипта в OptTree.ref).

    Ограниченность поля для работы @Apakhov’а и @VladisP’а была намеренной, т.к. этого было достаточно для выполнения содержательной части задачи.

  2. Ациклическая прогонка @Apakhov’а делает ненужной авторазметку прогоняемых функций в том виде, в каком она сейчас есть. Исходно разметка была призвана не допускать пометки $DRIVE для рекурсивных функций. Сейчас рекурсивные функции могут иметь метку $DRIVE, их прогонка не зациклится.

  3. Со специализацией без шаблона @VladisP’а становятся ненужными шаблоны в абстрактном синтаксическом дереве. Но, чтобы их удалить, нужны более глубокие правки.

  4. Да, авторазметка для специализации тоже становится ненужной.

  5. Основные компоненты для #314 уже реализованы (#251, #322, #340). Фактически в #314 нужно реализовать поддержку псевдокомментариев так, как она описана (и в следующем релизе удалить старый синтаксис).

  6. Написанный студентами код может быть неоптимальным, т.к. у них нет опыта в оптимизации Рефала.

  7. Новые оптимизации работают глубже, из-за чего могут выявиться проблемы в других частях системы. В частности, обостряются проблемы с раздуванием программ (#332). На данный момент проблема купирована в 54c28cad9921556d208bc43dc88f55943d7885cb.

  8. Хотя все автотесты выполнились, включая и случайные, тестовое покрытие, выполненное студентами неполное. Требуется более тщательное тестирование.

  9. Автотесты проверяют корректность. Содержательную сторону нужно тестировать вручную.

  10. Даже если обе оптимизации в отдельных ветках работали порознь, при работе вместе возможны проблемы.

  11. Можно удалить ObjectMatch.ref, т.к. новый алгоритм сопоставления покрывает этот случай.


В первую очередь нужно

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

Mazdaywik avatar Jun 26 '21 14:06 Mazdaywik

Самоприменение в режиме

set RLMAKE_FLAGS=-X-OiDPRS

прошло успешно. После самоприменения был сделан повторный запуск с ключами

set RLMAKE_FLAGS=-X-OiDS

и включённым профилированием. Профиль показал следующее:

Total time: 1590.76500 s
Total semisteps (function calls and closure unwraps): 782471744
Mean semistep time: 2.033000 us

PartiallyContainsSignature (0367) -> 146585.0 ms (9.21 %, += 9.21 %)                  rel step time 1.37
PartiallyContainsSignature$1?1 (0367) -> 131388.0 ms (8.26 %, += 17.47 %)              rel step time 1.22
PartiallyContainsSignature$2?2 (0367) -> 114076.0 ms (7.17 %, += 24.65 %)              rel step time 1.33
PartiallyContainsSignature$2?1 (0367) -> 95709.0 ms (6.02 %, += 30.66 %)              rel step time 1.11
ContainsSignature (0367) -> 91398.0 ms (5.75 %, += 36.41 %)                           rel step time 0.84
DoCheckExprPairForRelation$1?1 (0367) -> 63350.0 ms (3.98 %, += 40.39 %)              rel step time 2.94
DoCheckExprPairForRelation (0367) -> 63010.0 ms (3.96 %, += 44.35 %)                  rel step time 2.93
DoCheckExprPairForRelation$2?1 (0367) -> 62720.0 ms (3.94 %, += 48.29 %)              rel step time 2.92
Solve-Clashes (5826) -> 59211.0 ms (3.72 %, += 52.02 %)                               rel step time 5.00
GrowDriveTree:1@2 (5699) -> 37907.0 ms (2.38 %, += 54.40 %)                           rel step time 164.09
ApplyContraction-toExpr (5826) -> 33363.0 ms (2.10 %, += 56.50 %)                     rel step time 0.97
PartiallyContainsSignature$2?3 (0367) -> 33064.0 ms (2.08 %, += 58.57 %)              rel step time 0.51
ExtractVariables-Expr (0000) -> 17419.0 ms (1.10 %, += 59.67 %)                       rel step time 0.53
OutlineStrings (1650) -> 17047.0 ms (1.07 %, += 60.74 %)                              rel step time 4.37
ContainsSignature$5:1@1 (0367) -> 15771.0 ms (0.99 %, += 61.73 %)                     rel step time 0.75
GrowDriveTree (5699) -> 13744.0 ms (0.86 %, += 62.60 %)                               rel step time 59.49
ContainsSignature$5?1 (0367) -> 12505.0 ms (0.79 %, += 63.38 %)                       rel step time 0.59

(полный профиль: _profile_count.txt, _profile_time.txt)

ПОЛОВИНУ времени занимает проверка отношения Хигмана-Крускала! Значит, её надо переписывать.

В прошлом году @TonitaN интересовалась, не является ли отношение Хигмана-Крускала узким местом. Тогда не являлось, поскольку функция вызывалась относительно редко. Сейчас модуль прогонки фактически выполняет суперкомпиляцию с построением графа и перестройками сверху (своеобразными, но тем не менее). И теперь проверка этого отношения стала узким местом.

Mazdaywik avatar Jun 27 '21 07:06 Mazdaywik

Отношение Хигмана-Крускала оптимизировано:

Total time: 575.85900 s
Total semisteps (function calls and closure unwraps): 346857543
Mean semistep time: 1.660218 us

Solve-Clashes (5826) -> 54201.0 ms (9.41 %, += 9.41 %)                               rel step time 6.08
ApplyContraction-toExpr (5826) -> 31204.0 ms (5.42 %, += 14.83 %)                     rel step time 1.21
GrowDriveTree:1@2 (9075) -> 21601.0 ms (3.75 %, += 18.58 %)                           rel step time 145.19
OutlineStrings (3824) -> 15424.0 ms (2.68 %, += 21.26 %)                              rel step time 6.89
ExtractVariables-Expr (0000) -> 15149.0 ms (2.63 %, += 23.89 %)                       rel step time 0.67
GrowDriveTree (9075) -> 10161.0 ms (1.76 %, += 25.66 %)                               rel step time 68.30
IsTerm (5826) -> 9246.0 ms (1.61 %, += 27.26 %)                                      rel step time 0.67
ClearCoordinates (5826) -> 8940.0 ms (1.55 %, += 28.81 %)                            rel step time 0.70
SimplifyCoordinates-Expr (5826) -> 8666.0 ms (1.50 %, += 30.32 %)                    rel step time 0.83
IsSVarSubset (5826) -> 8604.0 ms (1.49 %, += 31.81 %)                                rel step time 0.63
SimplifyCoordinates-Expr-Inner (5826) -> 8362.0 ms (1.45 %, += 33.26 %)              rel step time 1.15
Add (0000) -> 7619.0 ms (1.32 %, += 34.59 %)                                         rel step time 0.70
Map@11 (5826) -> 7562.0 ms (1.31 %, += 35.90 %)                                      rel step time 0.75
Solve-Clashes$2?1 (5826) -> 6453.0 ms (1.12 %, += 37.02 %)                           rel step time 1.24
Solve-Clashes$3?1 (5826) -> 6341.0 ms (1.10 %, += 38.12 %)                           rel step time 1.23
DoGenSubst (2951) -> 6086.0 ms (1.06 %, += 39.18 %)                                  rel step time 14.52
Solve-Clashes$1?1 (5826) -> 5570.0 ms (0.97 %, += 40.15 %)                           rel step time 1.06
Solve-Clashes$1?2 (5826) -> 5473.0 ms (0.95 %, += 41.10 %)                           rel step time 1.74
Solve-Clashes$5?1 (5826) -> 5432.0 ms (0.94 %, += 42.04 %)                           rel step time 1.36
Solve-Clashes$8?1 (5826) -> 5307.0 ms (0.92 %, += 42.96 %)                           rel step time 1.33
Solve-Clashes$4?1 (5826) -> 5158.0 ms (0.90 %, += 43.86 %)                           rel step time 1.29
__Step-Drop (0000) -> 5137.0 ms (0.89 %, += 44.75 %)                                 rel step time 0.26
Unique (0000) -> 5100.0 ms (0.89 %, += 45.64 %)                                      rel step time 1.29
Solve-Clashes$9?1 (5826) -> 4938.0 ms (0.86 %, += 46.49 %)                           rel step time 1.24
Solve-Clashes$12?1 (5826) -> 4842.0 ms (0.84 %, += 47.33 %)                          rel step time 1.22
Solve-Clashes$13?1 (5826) -> 4787.0 ms (0.83 %, += 48.17 %)                          rel step time 1.21
Solve-Clashes$6?1 (5826) -> 4781.0 ms (0.83 %, += 49.00 %)                           rel step time 1.20
DoAddCoordinateLabels (5826) -> 4680.0 ms (0.81 %, += 49.81 %)                       rel step time 0.80
Solve-Clashes$7?1 (5826) -> 4625.0 ms (0.80 %, += 50.61 %)                           rel step time 1.16
Map@12 (5826) -> 4524.0 ms (0.79 %, += 51.40 %)                                      rel step time 0.68
CheckHKRelation (6259) -> 4344.0 ms (0.75 %, += 52.15 %)                             rel step time 2.42
…

(полный профиль: _profile_count.txt, _profile_time.txt)

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

Кроме того, на третьей и шестой строке находится GrowDriveTree, которую оптимизировать несложно (там есть потери, и соответственно, копирования переменных).

Значит, нужно думать, как оптимизировать сопоставление с образцом и GrowDriveTree.

Mazdaywik avatar Jun 27 '21 11:06 Mazdaywik

(комментарий не сворачивать, на него есть ссылка)

Функция GrowDriveTree скрылась с экранов радаров:

Total time: 583.17200 s
Total semisteps (function calls and closure unwraps): 346741271
Mean semistep time: 1.681865 us

Solve-Clashes (5826) -> 59036.0 ms (10.12 %, += 10.12 %)                               rel step time 6.54
ApplyContraction-toExpr (5826) -> 33258.0 ms (5.70 %, += 15.83 %)                     rel step time 1.27
OutlineStrings (3824) -> 17141.0 ms (2.94 %, += 18.77 %)                              rel step time 7.56
ExtractVariables-Expr (0000) -> 15008.0 ms (2.57 %, += 21.34 %)                       rel step time 0.66
ClearCoordinates (5826) -> 10479.0 ms (1.80 %, += 23.14 %)                            rel step time 0.81
IsSVarSubset (5826) -> 10393.0 ms (1.78 %, += 24.92 %)                                rel step time 0.75
IsTerm (5826) -> 9410.0 ms (1.61 %, += 26.53 %)                                      rel step time 0.67
SimplifyCoordinates-Expr (5826) -> 8961.0 ms (1.54 %, += 28.07 %)                    rel step time 0.85
SimplifyCoordinates-Expr-Inner (5826) -> 8435.0 ms (1.45 %, += 29.51 %)              rel step time 1.15
Map@11 (5826) -> 7725.0 ms (1.32 %, += 30.84 %)                                      rel step time 0.76
Add (0000) -> 7315.0 ms (1.25 %, += 32.09 %)                                         rel step time 0.67
Solve-Clashes$2?1 (5826) -> 7027.0 ms (1.20 %, += 33.30 %)                           rel step time 1.33
Solve-Clashes$4?1 (5826) -> 6469.0 ms (1.11 %, += 34.41 %)                           rel step time 1.60
Solve-Clashes$3?1 (5826) -> 6367.0 ms (1.09 %, += 35.50 %)                           rel step time 1.22
DoGenSubst (2951) -> 6021.0 ms (1.03 %, += 36.53 %)                                  rel step time 14.18
__Step-Drop (0000) -> 5803.0 ms (1.00 %, += 37.53 %)                                 rel step time 0.29
Unique (0000) -> 5770.0 ms (0.99 %, += 38.52 %)                                      rel step time 1.45
Solve-Clashes$9?1 (5826) -> 5624.0 ms (0.96 %, += 39.48 %)                           rel step time 1.40
Solve-Clashes$8?1 (5826) -> 5612.0 ms (0.96 %, += 40.44 %)                           rel step time 1.39
Solve-Clashes$1?2 (5826) -> 5567.0 ms (0.95 %, += 41.40 %)                           rel step time 1.75
Solve-Clashes$12?1 (5826) -> 5490.0 ms (0.94 %, += 42.34 %)                          rel step time 1.36
Solve-Clashes$13?1 (5826) -> 5448.0 ms (0.93 %, += 43.27 %)                          rel step time 1.36
Solve-Clashes$7?1 (5826) -> 5311.0 ms (0.91 %, += 44.18 %)                           rel step time 1.32
Solve-Clashes$5?1 (5826) -> 5248.0 ms (0.90 %, += 45.08 %)                           rel step time 1.30
Solve-Clashes$1?1 (5826) -> 5094.0 ms (0.87 %, += 45.96 %)                           rel step time 0.96
Solve-Clashes$6?1 (5826) -> 5012.0 ms (0.86 %, += 46.82 %)                           rel step time 1.24
AddContraction-Spec (5826) -> 4891.0 ms (0.84 %, += 47.66 %)                         rel step time 1.87
DoAddCoordinateLabels (5826) -> 4870.0 ms (0.84 %, += 48.49 %)                       rel step time 0.82

Что дальше нужно оптимизировать и как? Рассмотрим построчно.

  • Solve-Clashes — >10,12 %. Время её выполнения составляет 6,54 средних шага, т.к. в ней есть полиномиальная сложность — открытые переменные. Функция описана как набор из правил, каждое из которых ищет в системе применимый к нему терм при помощи открытой переменной.

    Заметим, в функции есть условия, и если условие не выполнилось, то последующее время выполнения профилировщик припишет не Solve-Clashes, а Solve-Clashes$k?m, что мы и видим в профиле. Заметим, что этих «условий» много и каждое из них отъедает около процента времени. Таким образом, Solve-Clashes по факту потребляет гораздо больше 10 %.

    Как её оптимизировать?

    • Можно собрать статистику, какие правила выполняются чаще и переместить их вверх.
    • Можно ввести частные случаи правил. Вместо, например, правила для e.X E : Pt P ввести отдельные правила для e.X E : X P, e.X E : s.X P, e.X E : (P′) P″, e.X E [X P′] P″, e.X E : t.Y P. Это позволит сократить число итераций за счёт удлинения самой итерации.
    • Можно поменять порядок итераций, перебирая не сначала правила, а потом клэши, а наоборот. Для первого клэша последовательно проверить все правила, выполнить применимое. Если применимо только правило для открытой переменной — положить в карман и перейти к следующему. Какой эффект смена итераций окажет на производительность — не понятно. Возможно, наоборот снизит быстродействие.
  • ApplyContraction-toExpr — 5,7 %. В текущей реализации при построении каждого нового сужения оно применяется (а) к предыдущим сужениям, (б) к уравнениям, (в) к присваиваниям. Это избыточно для ветвей, которые усекаются. Альтернативный вариант: сужения складывать по очереди в карман, в процессе решения применять их только к уравнениям. К набору параметров они будут применяться только при получении решения, к присваиваниям — перед построением симметричных клэшей.

  • OutlineStrings — 2,94 %. Функция в back-end’е, сейчас нас не интересует.

  • ExtractVariables-Expr — 2,57 %. Подозреваю, что это извлечения новых переменных из сужений в алгоритме прогонки. Эти вызовы можно устранить, если научить функцию Solve-Drive возвращать модифицированный список используемых переменных.

  • ClearCoordinates — 1,8 %. Функция эффективная, выполняется за 0,81 среднего шага. Все точки вызова по делу. Никак не оптимизируешь.

  • IsSVarSubset — 1,78 %, IsTerm — 1,61 %. Варианты:

    • Компилятор не способен оптимизировать вызовы этих простых функций, т.к. они вызываются из условий. Вопрос: имеет ли смысл встроить их вручную, размножив правила?
    • Добавление таксономии: термы и символы оборачивать, соответственно, в (T …) и (S …):
      • (Var 't' e._)(T (Var 't' e._))
      • (Brackets e._)(T (Brackets e._))
      • (ADT-Brackets e._)(T (ADT-Brackets e._))
      • (Symbol e._)(T (S (Symbol e.)))
      • (Var 's' e._)(T (S (Var 's' e._)))
      • (ClosureBrackets e._)(T (S (ClosureBrackets e._)))

    Преобразование применяется к обоим частям уравнения (либо только к левой?). В этом случае функции IsSVarSubset и IsTerm станут не нужны, т.к. эта же информация будет обретаться из образца. Но введение таксономии заметно усложнит применение подстановок.

  • SimplifyCoordinates-Expr — 1,54 %, SimplifyCoordinates-Expr-Inner — 1,45 %. Они вообще не нужны. Скопления координат вида … {a} {b} {c} … могут возникнуть при применении нескольких стирающих подстановок на смежные e-переменные, что довольно редко. Кроме того, эти скопления никак не мешают работе алгоритма. Поэтому нужно устранять скопления, возникающие на границах на верхнем уровне. А это уже не требует сканирования всего выражения в глубь.

  • Map@11 — 1.32 %. Надо по логу смотреть, что это. Но, судя по области видимости 5826, она из GenericMatch.ref.

Дальше разбирать не интересно.

Mazdaywik avatar Jun 27 '21 19:06 Mazdaywik

Комментарий не сворачивать, на него ссылка из https://github.com/bmstu-iu9/refal-5-lambda/issues/332#issuecomment-890483185.

Ещё один из возможных путей оптимизации — учёт частных случаев вида

e.X : P
t.X : Pt

Если P/Pt — жёсткие выражения, то их решением будут, соответственно, сужения e.X → P′ и t.X → Pt′, где P′ и Pt′, соответственно, повторяют по своей структуре P и Pt, но все переменные в них новые. Для образца с открытыми переменными эти переменные нужно оставлять как отдельные клэши.

Но пока не очевидно, часто ли будет разбор этого частного случая оправданным.

Mazdaywik avatar Jul 03 '21 07:07 Mazdaywik

Запустил самоприменение с ключами

set RLMAKE_FLAGS=-X-OiADPRS

Программа вылетела. Фрагмент профиля:

Total time: 4707.04700 s
Total semisteps (function calls and closure unwraps): 2000270899
Mean semistep time: 2.353205 us

Solve-Clashes$18?1 (5826) -> 315930.0 ms (6.71 %, += 6.71 %)                          rel step time 2.16
Solve-Clashes$15?1 (5826) -> 247027.0 ms (5.25 %, += 11.96 %)                          rel step time 1.69
IsSVarSubset (5826) -> 241713.0 ms (5.14 %, += 17.10 %)                                rel step time 0.55
IsTerm (5826) -> 215255.0 ms (4.57 %, += 21.67 %)                                      rel step time 0.59
Solve-Clashes$1?2 (5826) -> 203804.0 ms (4.33 %, += 26.00 %)                           rel step time 1.39
Solve-Clashes$10?2 (5826) -> 201480.0 ms (4.28 %, += 30.28 %)                          rel step time 1.38
Solve-Clashes$2?2 (5826) -> 196874.0 ms (4.18 %, += 34.46 %)                           rel step time 1.34
Solve-Clashes$9?1 (5826) -> 191243.0 ms (4.06 %, += 38.52 %)                           rel step time 1.31
Solve-Clashes$4?1 (5826) -> 190594.0 ms (4.05 %, += 42.57 %)                           rel step time 1.30
Solve-Clashes$11?2 (5826) -> 190188.0 ms (4.04 %, += 46.61 %)                          rel step time 1.30
Solve-Clashes$3?1 (5826) -> 185926.0 ms (3.95 %, += 50.56 %)                           rel step time 1.27
Solve-Clashes$8?1 (5826) -> 184881.0 ms (3.93 %, += 54.49 %)                           rel step time 1.26
Solve-Clashes$12?1 (5826) -> 184664.0 ms (3.92 %, += 58.41 %)                          rel step time 1.26
Solve-Clashes$13?1 (5826) -> 181657.0 ms (3.86 %, += 62.27 %)                          rel step time 1.24
Solve-Clashes$5?1 (5826) -> 181193.0 ms (3.85 %, += 66.12 %)                           rel step time 1.24
Solve-Clashes$14?1 (5826) -> 180313.0 ms (3.83 %, += 69.95 %)                          rel step time 1.23
Solve-Clashes$7?1 (5826) -> 179257.0 ms (3.81 %, += 73.76 %)                           rel step time 1.22
Solve-Clashes (5826) -> 170617.0 ms (3.62 %, += 77.39 %)                               rel step time 1.16
Solve-Clashes$6?1 (5826) -> 148309.0 ms (3.15 %, += 80.54 %)                           rel step time 1.01
Solve-Clashes$17?1 (5826) -> 135148.0 ms (2.87 %, += 83.41 %)                          rel step time 0.92
Solve-Clashes$11?1 (5826) -> 79453.0 ms (1.69 %, += 85.10 %)                          rel step time 0.54
Solve-Clashes$23=4@1 (5826) -> 77258.0 ms (1.64 %, += 86.74 %)                        rel step time 1.06
Solve-Clashes$10?1 (5826) -> 75524.0 ms (1.60 %, += 88.34 %)                          rel step time 0.52
Solve-Clashes$1?1 (5826) -> 74487.0 ms (1.58 %, += 89.92 %)                           rel step time 0.51

Вызов, на котором упало:

   .   .   .   .   .   .   .   <Solve-Clashes 
   .   .   .   .   .   .   .   .(('ePrefixFileName' )
   .   .   .   .   .   .   .   . ('tConfig' )
   .   .   .   .   .   .   .   . ('eCall' )
   .   .   .   .   .   .   .   . ('eCall3' )
   .   .   .   .   .   .   .   . ('eCall' )
   .   .   .   .   .   .   .   . ('eCall3' )
   .   .   .   .   .   .   .   . ('ePrefixFileName' )
   .   .   .   .   .   .   .   . ('tConfig' ))
   .   .   .   .   .   .   .   .(#None 
   .   .   .   .   .   .   .   . ((#Var 'ePrefixFileName' )':' 
   .   .   .   .   .   .   .   .  (#Var 'ePrefixFileName' ))
   .   .   .   .   .   .   .   . ((#Var 'tConfig' )':' 
   .   .   .   .   .   .   .   .  (#Var 'tConfig' )))
   .   .   .   .   .   .   .   .((('{' 1 '}' )
   .   .   .   .   .   .   .   .  (#ClosureBrackets 
   .   .   .   .   .   .   .   .   (#Symbol #Name 'Link-WithPrefix' #SUF '\\' 1 '@' 1 )
   .   .   .   .   .   .   .   .   (#Brackets 
   .   .   .   .   .   .   .   .   .(#Var 'ePrefixFileName' ))
   .   .   .   .   .   .   .   .   (#Var 'tConfig' ))
   .   .   .   .   .   .   .   .  ('{' 2 '}' ))':' 
   .   .   .   .   .   .   .   . ((#Symbol #Identifier 'NoConfig' )))
   .   .   .   .   .   .   .   .(()':' 
   .   .   .   .   .   .   .   . ())
   .   .   .   .   .   .   .   .()
   .   .   .   .   .   .   .   .<Solve-Clashes$8?1 
   .   .   .   .   .   .   .   . (#ClosureBrackets 
   .   .   .   .   .   .   .   .  (#Symbol #Name 'Link-WithPrefix' #SUF '\\' 1 '@' 1 )
   .   .   .   .   .   .   .   .  (#Brackets 
   .   .   .   .   .   .   .   .   (#Var 'ePrefixFileName' ))
   .   .   .   .   .   .   .   .  (#Var 'tConfig' ))>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

Есть над чем подумать.

Mazdaywik avatar Jul 03 '21 12:07 Mazdaywik

Многие из предложений Solve-Clashes имеют вид:

  /* {m} [X E] {n} : [X P]   ↦  {m} E {n} : P */
  (e.UsedVars) (e.Contrs) e.ClashesStart
  ((('{'s.M'}') t.L ('{'s.N'}')) ':' (t.R))
  e.ClashesEnd (e.Assigns)
    , t.L : (ADT-Brackets (e.Name) e.LBody)
    , t.R : (ADT-Brackets (e.Name) e.RBody)
    = <Solve-Clashes
        (e.UsedVars)
        (e.Contrs) e.ClashesStart
        <SimplifyCoordinates-Clash
          ((('{'s.M'}') e.LBody ('{'s.N'}')) ':' (e.RBody))
        >
        e.ClashesEnd (e.Assigns)
      >;

  /* {m} [X E] {n} : [Y P]  ↦  нет решений */
  (e.UsedVars) (e.Contrs) e.ClashesStart
  ((('{'s.M'}') t.L ('{'s.N'}')) ':' (t.R))
  e.ClashesEnd (e.Assigns)
    , t.L : (ADT-Brackets e._)
    , t.R : (ADT-Brackets e._)
    = /* нет решений */;

Условия здесь являются условиями-сужениями (#257), но на них затрачиваются дополнительные шаги Рефал-машины. Можно либо реализовать #257, либо на данный момент просто встроить.

Mazdaywik avatar Jul 03 '21 19:07 Mazdaywik

Самоприменение выполняется очень долго (около 10 минут) из-за того, что специализируются функции в SR-Lexer.sref. Почему?

$SPEC DirectiveTail (e.acc) e.text;

DirectiveTail {
  (e.Accum) 'A' e.Text = <DirectiveTail (e.Accum 'A') e.Text>;
  (e.Accum) 'B' e.Text = <DirectiveTail (e.Accum 'B') e.Text>;
  (e.Accum) 'C' e.Text = <DirectiveTail (e.Accum 'C') e.Text>;

Ранее эти директивы $SPEC были добавлены, чтобы подавить автоматическую специализацию этих функций в режиме -OA, опять же, для экономии времени. Но сейчас, с новым алгоритмом специализации они выполняют прямо противоположную функцию — принудительно включают специализацию.

Значит, нужно реализовать подавление специализации (да и прогонки тоже) псевдокомментарием *$NOOPT, как описано в #314.

Mazdaywik avatar Jul 04 '21 06:07 Mazdaywik

Повторил замер с

set RLMAKE_FLAGS=-X-OiADPRS

Программа вылетает так:

D:\Mazdaywik\Documents\Refal-5-lambda\src\compiler>makeself.bat
*Compiling main.ref:

STEP LIMIT REACHED (2000000000)


Total program time: 4821.46900 seconds (100.0 %).
(Total refal time): 3723.66000 seconds (77.2 %).
Runtime time overhead: 1096.90000 seconds (22.8 %).
Open e-loop time (clear): 1083.45500 seconds (22.5 %).
Linear pattern time: 1076.80000 seconds (22.3 %).
t- and e-var copy time: 811.66800 seconds (16.8 %).
Linear result time: 743.60600 seconds (15.4 %).
Repeated t-var match time (inside e-loops): 7.06600 seconds (0.1 %).
Repeated e-var match time (outside e-loops): 1.00100 seconds (0.0 %).
Native time: 0.90900 seconds (0.0 %).
Repeated e-var match time (inside e-loops): 0.04800 seconds (0.0 %).
Repeated t-var match time (outside e-loops): 0.01600 seconds (0.0 %).

STEP LIMIT REACHED (2000000001)

Step count 2000000001
Identifiers allocated: 2023
Memory used 987000 nodes, 987000 * 16 = 15792000 bytes
ERROR: rlc-core returned code 103

т.е. не успевает скомпилироваться даже самый первый файл.

Вывод счётчика шагов:

Total time: 4821.12500 s
Total semisteps (function calls and closure unwraps): 2000270899
Mean semistep time: 2.410236 us

IsSVarSubset~13 (9838) -> 186664626 (9.33 %, += 9.33 %)                             rel step time 0.49
IsTerm~13 (9838) -> 155595956 (7.78 %, += 17.11 %)                                   rel step time 0.54
Solve-Clashes~13 (9838) -> 62259023 (3.11 %, += 20.22 %)                            rel step time 1.28
Solve-Clashes~13$1?1 (9838) -> 62231402 (3.11 %, += 23.33 %)                        rel step time 0.57
Solve-Clashes~13$2?1 (9838) -> 62227391 (3.11 %, += 26.45 %)                        rel step time 0.58
Solve-Clashes~13$3?1 (9838) -> 62225399 (3.11 %, += 29.56 %)                        rel step time 1.28
Solve-Clashes~13$1?2 (9838) -> 62222516 (3.11 %, += 32.67 %)                        rel step time 1.42
Solve-Clashes~13$4?1 (9838) -> 62217744 (3.11 %, += 35.78 %)                        rel step time 1.28
Solve-Clashes~13$7?1 (9838) -> 62217743 (3.11 %, += 38.89 %)                        rel step time 1.25
Solve-Clashes~13$6?1 (9838) -> 62217743 (3.11 %, += 42.00 %)                        rel step time 1.01
Solve-Clashes~13$5?1 (9838) -> 62217743 (3.11 %, += 45.11 %)                        rel step time 1.24
Solve-Clashes~13$8?1 (9838) -> 62217741 (3.11 %, += 48.22 %)                        rel step time 1.23
Solve-Clashes~13$9?1 (9838) -> 62217726 (3.11 %, += 51.33 %)                        rel step time 1.35
Solve-Clashes~13$10?1 (9838) -> 62217726 (3.11 %, += 54.44 %)                       rel step time 0.59
Solve-Clashes~13$11?1 (9838) -> 62217719 (3.11 %, += 57.55 %)                       rel step time 0.59
Solve-Clashes~13$12?1 (9838) -> 62217618 (3.11 %, += 60.66 %)                       rel step time 1.28
Solve-Clashes~13$13?1 (9838) -> 62217145 (3.11 %, += 63.77 %)                       rel step time 1.28
Solve-Clashes~13$14?1 (9838) -> 62216755 (3.11 %, += 66.88 %)                       rel step time 1.32
Solve-Clashes~13$15?1 (9838) -> 62214915 (3.11 %, += 69.99 %)                       rel step time 1.73
Solve-Clashes~13$18?1 (9838) -> 62211248 (3.11 %, += 73.10 %)                       rel step time 2.01
Solve-Clashes~13$2?2 (9838) -> 62210282 (3.11 %, += 76.21 %)                        rel step time 1.34
Solve-Clashes~13$10?2 (9838) -> 62208620 (3.11 %, += 79.32 %)                       rel step time 1.43
Solve-Clashes~13$11?2 (9838) -> 62208613 (3.11 %, += 82.43 %)                       rel step time 1.33
Solve-Clashes~13$17?1 (9838) -> 62208343 (3.11 %, += 85.54 %)                       rel step time 0.91
Solve-Clashes~13$23?1 (9838) -> 31119438 (1.56 %, += 87.10 %)                       rel step time 0.67

Вывод: таксономию делать надо, чтобы программа не выходила за лимит счётчика. Также надо убрать избыточные условия-сужения: с ними код станет не только быстрее (лишние шаги), но и понятнее.

Mazdaywik avatar Jul 05 '21 08:07 Mazdaywik

Оптимизация функции ExtractVariables-Expr ничего толком не дала. Оптимизация SimplifyCoordinates-Expr дала крошечное ускорение.

Следующим шагом будет оптимизация Solve-Clashes путём встраивания простых условий-сужений.

Mazdaywik avatar Jul 18 '21 08:07 Mazdaywik

Встраивание условий-сужений заметно ускорило работу компилятора (отсечка 50 %):

Total time: 343.89000 s
Total semisteps (function calls and closure unwraps): 286783977
Mean semistep time: 1.199126 us

Solve-Clashes (5021) -> 46845.0 ms (13.62 %, += 13.62 %)                               rel step time 7.28
ApplyContraction-toExpr (5021) -> 23952.0 ms (6.97 %, += 20.59 %)                     rel step time 1.28
OutlineStrings (3824) -> 12158.0 ms (3.54 %, += 24.12 %)                              rel step time 7.53
ExtractVariables-Expr (0000) -> 11265.0 ms (3.28 %, += 27.40 %)                       rel step time 0.70
ClearCoordinates (5021) -> 6928.0 ms (2.01 %, += 29.41 %)                            rel step time 0.75
SimplifyCoordinates-Expr (5021) -> 6623.0 ms (1.93 %, += 31.34 %)                    rel step time 0.89
Map@14 (5021) -> 6121.0 ms (1.78 %, += 33.12 %)                                      rel step time 0.85
Add (0000) -> 6067.0 ms (1.76 %, += 34.88 %)                                         rel step time 0.77
Unique (0000) -> 4509.0 ms (1.31 %, += 36.19 %)                                      rel step time 1.58
IsTerm (5021) -> 4417.0 ms (1.28 %, += 37.48 %)                                      rel step time 0.71
DoGenSubst (2951) -> 4319.0 ms (1.26 %, += 38.73 %)                                  rel step time 14.26
__Step-Drop (0000) -> 3876.0 ms (1.13 %, += 39.86 %)                                 rel step time 0.27
DoAddCoordinateLabels (5021) -> 3549.0 ms (1.03 %, += 40.89 %)                       rel step time 0.84
Map@15 (5021) -> 3537.0 ms (1.03 %, += 41.92 %)                                      rel step time 0.73
ApplyContraction-toContraction (5021) -> 3521.0 ms (1.02 %, += 42.95 %)              rel step time 0.66
CheckHKRelation (6259) -> 3514.0 ms (1.02 %, += 43.97 %)                             rel step time 2.71
Map@9 (5021) -> 3132.0 ms (0.91 %, += 44.88 %)                                       rel step time 0.65
AddContraction-Spec (5021) -> 2936.0 ms (0.85 %, += 45.73 %)                         rel step time 1.58
Map@16 (5021) -> 2801.0 ms (0.81 %, += 46.55 %)                                      rel step time 0.69
Map@15 (1279) -> 2773.0 ms (0.81 %, += 47.35 %)                                      rel step time 1.97
Solve-SymmClashes-Aux (5021) -> 2709.0 ms (0.79 %, += 48.14 %)                       rel step time 6.63
Divmod (0000) -> 2660.0 ms (0.77 %, += 48.91 %)                                      rel step time 0.70
GenCommand-RASL (4049) -> 2539.0 ms (0.74 %, += 49.65 %)                             rel step time 1.57
Add-Digits (7068) -> 2286.0 ms (0.66 %, += 50.32 %)                                  rel step time 0.29

_profile_time.txt

Total time: 343.89000 s
Total semisteps (function calls and closure unwraps): 286783977
Mean semistep time: 1.199126 us

ApplyContraction-toExpr (5021) -> 15577476 (5.43 %, += 5.43 %)                     rel step time 1.28
ExtractVariables-Expr (0000) -> 13443652 (4.69 %, += 10.12 %)                       rel step time 0.70
__Step-Drop (0000) -> 12092369 (4.22 %, += 14.34 %)                                 rel step time 0.27
ClearCoordinates (5021) -> 7713884 (2.69 %, += 17.03 %)                            rel step time 0.75
Add (0000) -> 6535437 (2.28 %, += 19.30 %)                                         rel step time 0.77
Add-Digits (7068) -> 6518060 (2.27 %, += 21.58 %)                                  rel step time 0.29
SimplifyCoordinates-Expr (5021) -> 6222934 (2.17 %, += 23.75 %)                    rel step time 0.89
Map@14 (5021) -> 6034299 (2.10 %, += 25.85 %)                                      rel step time 0.85
Solve-Clashes (5021) -> 5366900 (1.87 %, += 27.72 %)                               rel step time 7.28
IsTerm (5021) -> 5195326 (1.81 %, += 29.53 %)                                      rel step time 0.71
ApplyContraction-toContraction (5021) -> 4479978 (1.56 %, += 31.10 %)              rel step time 0.66
Map@9 (5021) -> 4026433 (1.40 %, += 32.50 %)                                       rel step time 0.65
Map@15 (5021) -> 4026205 (1.40 %, += 33.90 %)                                      rel step time 0.73
DoAddCoordinateLabels (5021) -> 3543061 (1.24 %, += 35.14 %)                       rel step time 0.84
Map@10 (5021) -> 3383213 (1.18 %, += 36.32 %)                                      rel step time 0.51
Map@16 (5021) -> 3382663 (1.18 %, += 37.50 %)                                      rel step time 0.69
Divmod-Digits (7068) -> 3281572 (1.14 %, += 38.64 %)                               rel step time 0.29
Divmod (0000) -> 3169243 (1.11 %, += 39.75 %)                                      rel step time 0.70
SimplifyCoordinates-Clash (5021) -> 3136071 (1.09 %, += 40.84 %)                   rel step time 0.55
ApplyContraction-toEquation (5021) -> 2471916 (0.86 %, += 41.70 %)                 rel step time 0.75
Unique (0000) -> 2373836 (0.83 %, += 42.53 %)                                      rel step time 1.58
ExtractVariables-Sentences (7483) -> 1991204 (0.69 %, += 43.23 %)                  rel step time 0.62
SimplifyCoordinates-Assign (5021) -> 1828332 (0.64 %, += 43.86 %)                  rel step time 0.75
ApplyContraction-toAssign (5021) -> 1828332 (0.64 %, += 44.50 %)                   rel step time 0.62
AllBrackets (6259) -> 1805060 (0.63 %, += 45.13 %)                                 rel step time 0.41
SimplifyCoordinates (5021) -> 1554517 (0.54 %, += 45.67 %)                         rel step time 0.52
AddContraction-Spec (5021) -> 1554517 (0.54 %, += 46.21 %)                         rel step time 1.58
Map@5 (5021) -> 1550963 (0.54 %, += 46.76 %)                                       rel step time 0.78
Map@4 (0035) -> 1541014 (0.54 %, += 47.29 %)                                       rel step time 0.64
Solve-Clashes$23?1 (5021) -> 1514309 (0.53 %, += 47.82 %)                          rel step time 1.05
HasTopLevelCoordinateLabels (5021) -> 1507602 (0.53 %, += 48.35 %)                 rel step time 0.76
DoMapAccum@16 (3824) -> 1502419 (0.52 %, += 48.87 %)                               rel step time 0.74
ConvertOneInterpretCommand (3824) -> 1502419 (0.52 %, += 49.39 %)                  rel step time 0.71
SetScopeIDs-Command (0035) -> 1502419 (0.52 %, += 49.92 %)                         rel step time 0.80
OutlineConstants-OneCommand (0035) -> 1502419 (0.52 %, += 50.44 %)                 rel step time 0.94

_profile_count.txt

Общее время работы снизилось до 343 секунд (против 427 в 77172cd), число полушагов — до 286 783 977 (против 346 741 271 в https://github.com/bmstu-iu9/refal-5-lambda/issues/359#issuecomment-869212614).

Верхние строчки рейтинга (по времени) сейчас выглядят так:

Solve-Clashes (5021) -> 46845.0 ms (13.62 %, += 13.62 %)                               rel step time 7.28
ApplyContraction-toExpr (5021) -> 23952.0 ms (6.97 %, += 20.59 %)                     rel step time 1.28
OutlineStrings (3824) -> 12158.0 ms (3.54 %, += 24.12 %)                              rel step time 7.53
ExtractVariables-Expr (0000) -> 11265.0 ms (3.28 %, += 27.40 %)                       rel step time 0.70
ClearCoordinates (5021) -> 6928.0 ms (2.01 %, += 29.41 %)                            rel step time 0.75
SimplifyCoordinates-Expr (5021) -> 6623.0 ms (1.93 %, += 31.34 %)                    rel step time 0.89
  • Большую долю времени по-прежнему занимает Solve-Clashes, однако, SolveClashes$k?m в списке почти не видно.
  • Вторая строчка относится к применению сужений (ApplyContraction-toExpr). Остаётся верным замечание про то, что применение сужений нужно откладывать: применять сужения к неполному решению (сужения + присваивания) преждевременно, т.к. ветка может отсечься. Достаточно применять сужения к клэшам. Более того, ApplyContraction-toExpr лидирует в рейтинге числа шагов (см. ниже).
  • Третья строчка относится к back-end’у, не интересно.
  • С ExtractVariables-Expr нужно разбираться. Возможно, она вызывается избыточное количество раз.
  • Остальные функции по делу.

Рейтинг по числу шагов:

ApplyContraction-toExpr (5021) -> 15577476 (5.43 %, += 5.43 %)                     rel step time 1.28
ExtractVariables-Expr (0000) -> 13443652 (4.69 %, += 10.12 %)                       rel step time 0.70
__Step-Drop (0000) -> 12092369 (4.22 %, += 14.34 %)                                 rel step time 0.27
ClearCoordinates (5021) -> 7713884 (2.69 %, += 17.03 %)                            rel step time 0.75
Add (0000) -> 6535437 (2.28 %, += 19.30 %)                                         rel step time 0.77
Add-Digits (7068) -> 6518060 (2.27 %, += 21.58 %)                                  rel step time 0.29
SimplifyCoordinates-Expr (5021) -> 6222934 (2.17 %, += 23.75 %)                    rel step time 0.89
Map@14 (5021) -> 6034299 (2.10 %, += 25.85 %)                                      rel step time 0.85
Solve-Clashes (5021) -> 5366900 (1.87 %, += 27.72 %)                               rel step time 7.28
IsTerm (5021) -> 5195326 (1.81 %, += 29.53 %)                                      rel step time 0.71
ApplyContraction-toContraction (5021) -> 4479978 (1.56 %, += 31.10 %)              rel step time 0.66

Тут никаких новых интересных выводов, разве что IsTerm вызывается относительно редко (а IsSVarSubset вообще не вошла в отсечку 50 %), а значит, таксономия неактуальна.

Вывод

  • Откладывать применение сужений.
  • Понять, не часто ли вызывается ExtractVariables-Expr.

Mazdaywik avatar Jul 18 '21 15:07 Mazdaywik

Выполнил замер с опцией

set RLMAKE_FLAGS=-X-OiADPRS

Вот как вылетел компилятор:

D:\…\src\compiler>makeself.bat
*Compiling main.ref:

STEP LIMIT REACHED (2000000000)


Total program time: 5364.75000 seconds (100.0 %).
(Total refal time): 4708.61000 seconds (87.8 %).
Open e-loop time (clear): 2154.82000 seconds (40.2 %).
Linear pattern time: 1392.81200 seconds (26.0 %).
Linear result time: 946.86400 seconds (17.6 %).
Runtime time overhead: 655.42400 seconds (12.2 %).
t- and e-var copy time: 210.97100 seconds (3.9 %).
Repeated e-var match time (outside e-loops): 2.93600 seconds (0.1 %).
Native time: 0.71600 seconds (0.0 %).
Repeated t-var match time (outside e-loops): 0.09600 seconds (0.0 %).
Repeated t-var match time (inside e-loops): 0.08000 seconds (0.0 %).
Repeated e-var match time (inside e-loops): 0.03100 seconds (0.0 %).

STEP LIMIT REACHED (2000000001)

Step count 2000000001
Identifiers allocated: 2501
Memory used 987000 nodes, 987000 * 16 = 15792000 bytes
ERROR: rlc-core returned code 103

Аварийный дамп:


STEP LIMIT REACHED (2000000000)


STEP NUMBER 2000000000

PRIMARY ACTIVE EXPRESSION:

<SeparateTermLeft$1?1 #True >

…
   .   .   .   .   .   .   .   .<SeparateTermLeft 
   .   .   .   .   .   .   .   . ('{' 1 '}' )
   .   .   .   .   .   .   .   . (#ClosureBrackets 
   .   .   .   .   .   .   .   .  (#Symbol #Name 'Link-WithPrefix' #SUF '\\' 1 '@' 1 )
   .   .   .   .   .   .   .   .  (#Brackets 
   .   .   .   .   .   .   .   .   (#Var 'ePrefixFileName' ))
   .   .   .   .   .   .   .   .  (#Var 'tConfig' ))
   .   .   .   .   .   .   .   . ('{' 2 '}' )
   .   .   .   .   .   .   .   . <SeparateTermLeft$1?1 #True >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>

Счётчик шагов:

Total time: 5364.43700 s
Total semisteps (function calls and closure unwraps): 2000274937
Mean semistep time: 2.681850 us

IsTerm (5021) -> 426697854 (21.33 %, += 21.33 %)                                      rel step time 0.38
Solve-Clashes (5021) -> 284478705 (14.22 %, += 35.55 %)                               rel step time 4.32
Solve-Clashes$23?1 (5021) -> 142229280 (7.11 %, += 42.66 %)                          rel step time 0.42
HasTopLevelCoordinateLabels (5021) -> 142229277 (7.11 %, += 49.77 %)                 rel step time 0.26
Eq (5021) -> 142225251 (7.11 %, += 56.89 %)                                          rel step time 0.25
Solve-Clashes$23?2 (5021) -> 142224358 (7.11 %, += 64.00 %)                          rel step time 0.37
Solve-Clashes$23?3 (5021) -> 142224039 (7.11 %, += 71.11 %)                          rel step time 0.65
SeparateTermLeft (5021) -> 142224039 (7.11 %, += 78.22 %)                            rel step time 0.68
Solve-Clashes$23=4@1 (5021) -> 142224038 (7.11 %, += 85.33 %)                        rel step time 0.71
SeparateTermLeft$1?1 (5021) -> 142222353 (7.11 %, += 92.44 %)                        rel step time 0.44
SeparateTermLeft$1:1@1 (5021) -> 142222353 (7.11 %, += 99.55 %)                      rel step time 0.46
AllBrackets (6259) -> 643695 (0.03 %, += 99.58 %)                                 rel step time 0.24
CheckHKRelation (6259) -> 444388 (0.02 %, += 99.60 %)                             rel step time 1.27
CheckHKRelation-Term (6259) -> 418090 (0.02 %, += 99.62 %)                        rel step time 0.39
CheckHKRelation$4?1 (6259) -> 418090 (0.02 %, += 99.64 %)                         rel step time 0.34
CheckHKRelation$5?1 (6259) -> 418057 (0.02 %, += 99.66 %)                         rel step time 0.36
ExtractVariables-Expr (0000) -> 366052 (0.02 %, += 99.68 %)                       rel step time 0.34

Счётчик времени:

Total time: 5364.43700 s
Total semisteps (function calls and closure unwraps): 2000274937
Mean semistep time: 2.681850 us

Solve-Clashes (5021) -> 3295841.0 ms (61.44 %, += 61.44 %)                               rel step time 4.32
IsTerm (5021) -> 439929.0 ms (8.20 %, += 69.64 %)                                      rel step time 0.38
Solve-Clashes$23=4@1 (5021) -> 270802.0 ms (5.05 %, += 74.69 %)                        rel step time 0.71
SeparateTermLeft (5021) -> 258573.0 ms (4.82 %, += 79.51 %)                            rel step time 0.68
Solve-Clashes$23?3 (5021) -> 247655.0 ms (4.62 %, += 84.12 %)                          rel step time 0.65
SeparateTermLeft$1:1@1 (5021) -> 176353.0 ms (3.29 %, += 87.41 %)                      rel step time 0.46
SeparateTermLeft$1?1 (5021) -> 166080.0 ms (3.10 %, += 90.51 %)                        rel step time 0.44
Solve-Clashes$23?1 (5021) -> 161290.0 ms (3.01 %, += 93.51 %)                          rel step time 0.42
Solve-Clashes$23?2 (5021) -> 141704.0 ms (2.64 %, += 96.16 %)                          rel step time 0.37
HasTopLevelCoordinateLabels (5021) -> 99924.0 ms (1.86 %, += 98.02 %)                 rel step time 0.26
Eq (5021) -> 95147.0 ms (1.77 %, += 99.79 %)                                          rel step time 0.25
CheckHKRelation (6259) -> 1510.0 ms (0.03 %, += 99.82 %)                             rel step time 1.27
Map@15 (1279) -> 547.0 ms (0.01 %, += 99.83 %)                                      rel step time 1.26
CheckHKRelation-Term (6259) -> 437.0 ms (0.01 %, += 99.84 %)                        rel step time 0.39
AllBrackets (6259) -> 407.0 ms (0.01 %, += 99.85 %)                                 rel step time 0.24
CheckHKRelation$5?1 (6259) -> 406.0 ms (0.01 %, += 99.85 %)                         rel step time 0.36
CheckHKRelation$4?1 (6259) -> 378.0 ms (0.01 %, += 99.86 %)                         rel step time 0.34

Вот предложение Solve-Clashes$23: https://github.com/bmstu-iu9/refal-5-lambda/blob/40b525fe60164085c14a514ec67fb8ce6740e775/src/compiler/GenericMatch.ref#L744-L759

  • Вызов функции HasTopLevelCoordinateLabels в нём и следующем предложении совершенно избыточен.
  • В функциях SeparateTermLeft и SeparateTermRight вызов IsTerm избыточен, т.к. его можно считать предусловием.
  • От функции Eq внутри самих этих двух функций также можно избавиться.
  • В SeparateTermLeft вызов HasTopLevelCoordinateLabels избыточен в силу использования открытой переменной.
  • В SeparateTermRight можно избавиться от HasTopLevelCoordinateLabels, организовав более эффективный поиск последней координаты. Но вообще, в идеале там нужно удлинение справа (#175).

Выше перечислены способы уменьшить число шагов.

Mazdaywik avatar Jul 18 '21 18:07 Mazdaywik

Повторил замер с опциями

set RLMAKE_FLAGS=-X-OiADPRS

Компилятор вылетел также, как и раньше, но до вылета прошло гораздо больше времени:

D:\Mazdaywik\Documents\Refal-5-lambda\src\compiler>makeself.bat
*Compiling main.ref:

STEP LIMIT REACHED (2000000000)


Total program time: 8114.34400 seconds (100.0 %).
(Total refal time): 7427.20300 seconds (91.5 %).
Open e-loop time (clear): 3873.17600 seconds (47.7 %).
Linear pattern time: 2142.26300 seconds (26.4 %).
Linear result time: 1208.30800 seconds (14.9 %).
Runtime time overhead: 686.37500 seconds (8.5 %).
t- and e-var copy time: 203.24900 seconds (2.5 %).
Native time: 0.76600 seconds (0.0 %).
Repeated t-var match time (inside e-loops): 0.09600 seconds (0.0 %).
Repeated e-var match time (inside e-loops): 0.04800 seconds (0.0 %).
Repeated t-var match time (outside e-loops): 0.04700 seconds (0.0 %).
Repeated e-var match time (outside e-loops): 0.01600 seconds (0.0 %).

STEP LIMIT REACHED (2000000001)

Step count 2000000001
Identifiers allocated: 2502
Memory used 987000 nodes, 987000 * 16 = 15792000 bytes
ERROR: rlc-core returned code 103

Профиль по шагам:

Total time: 8114.03100 s
Total semisteps (function calls and closure unwraps): 2000274937
Mean semistep time: 4.056458 us

Solve-Clashes (6995) -> 497819123 (24.89 %, += 24.89 %)                               rel step time 2.97
IsTerm (6995) -> 497811220 (24.89 %, += 49.77 %)                                      rel step time 0.27
Solve-Clashes$23?1 (6995) -> 248899489 (12.44 %, += 62.22 %)                          rel step time 0.29
Solve-Clashes$23?2 (6995) -> 248894566 (12.44 %, += 74.66 %)                          rel step time 0.43
Solve-Clashes$23=3@1 (6995) -> 248894247 (12.44 %, += 87.10 %)                        rel step time 0.47
SeparateTermLeft (6995) -> 248894247 (12.44 %, += 99.55 %)                            rel step time 0.37
AllBrackets (6259) -> 643695 (0.03 %, += 99.58 %)                                 rel step time 0.14
CheckHKRelation (6259) -> 444388 (0.02 %, += 99.60 %)                             rel step time 0.74
CheckHKRelation-Term (6259) -> 418090 (0.02 %, += 99.62 %)                        rel step time 0.24

Профиль по времени:

Total time: 8114.03100 s
Total semisteps (function calls and closure unwraps): 2000274937
Mean semistep time: 4.056458 us

Solve-Clashes (6995) -> 6000217.0 ms (73.95 %, += 73.95 %)                               rel step time 2.97
IsTerm (6995) -> 537182.0 ms (6.62 %, += 80.57 %)                                      rel step time 0.27
Solve-Clashes$23=3@1 (6995) -> 474855.0 ms (5.85 %, += 86.42 %)                        rel step time 0.47
Solve-Clashes$23?2 (6995) -> 431259.0 ms (5.31 %, += 91.74 %)                          rel step time 0.43
SeparateTermLeft (6995) -> 370919.0 ms (4.57 %, += 96.31 %)                            rel step time 0.37
Solve-Clashes$23?1 (6995) -> 287943.0 ms (3.55 %, += 99.86 %)                          rel step time 0.29
CheckHKRelation (6259) -> 1337.0 ms (0.02 %, += 99.87 %)                             rel step time 0.74

В профиле отсутствуют бестолковые вызовы. Долгое время работы обусловлено тем, что большинство шагов — это Solve-Clashes, которая осуществляет поиск по открытым e-переменным.

Похоже, что где-то что-то зацикливается.

Mazdaywik avatar Jul 19 '21 20:07 Mazdaywik

Замер с опциями

set RLMAKE_FLAGS=-X-OiADPRS

по-прежнему падает. На этот раз так:

D:\Mazdaywik\Documents\Refal-5-lambda\src\compiler>makeself.bat
*Compiling main.ref:
+Linking D:\Mazdaywik\Documents\Refal-5-lambda\lib\references\Library.rasl
+Linking D:\Mazdaywik\Documents\Refal-5-lambda\lib\references\LibraryEx.rasl
*Compiling ParseCmdLine.ref:
+Linking D:\Mazdaywik\Documents\Refal-5-lambda\lib\references\GetOpt.rasl
*Compiling Config.ref:
*Compiling ..\common\Version.ref:
*Compiling Log.ref:
*Compiling DisplayName.ref:
*Compiling ..\common\Escape.ref:
*Compiling Log-AST.ref:
*Compiling Error.ref:
*Compiling ..\common\FindFile.ref:
+Linking D:\Mazdaywik\Documents\Refal-5-lambda\lib\references\Platform.rasl
*Compiling Engine.ref:
*Compiling Checker.ref:
*Compiling GenericMatch.ref:

STEP LIMIT REACHED (2000000000)


Total program time: 2945.89000 seconds (100.0 %).
(Total refal time): 2304.00000 seconds (78.2 %).
Linear pattern time: 740.39200 seconds (25.1 %).
t- and e-var copy time: 596.31900 seconds (20.2 %).
Runtime time overhead: 595.68100 seconds (20.2 %).
Linear result time: 438.83900 seconds (14.9 %).
Open e-loop time (clear): 436.46300 seconds (14.8 %).
Repeated t-var match time (inside e-loops): 62.71300 seconds (2.1 %).
Native time: 44.84600 seconds (1.5 %).
Repeated e-var match time (inside e-loops): 17.78300 seconds (0.6 %).
Repeated t-var match time (outside e-loops): 7.30300 seconds (0.2 %).
Repeated e-var match time (outside e-loops): 4.18800 seconds (0.1 %).
Context copy time: 1.36300 seconds (0.0 %).

STEP LIMIT REACHED (2000000001)

Step count 2000000001
Identifiers allocated: 2502
Memory used 34126000 nodes, 34126000 * 16 = 546016000 bytes
ERROR: rlc-core returned code 103

До падения компилятор успел прожевать гораздо больше файлов. Компилятор упал на back-end’е, так что это не зависание:

<FilterPatternPos 25 
 (3 24 32 
  (24 32 1 #HalfReuse )
  (25 33 1 #HalfReuse )
  (26 34 1 #HalfReuse ))>

Профиль по шагам:

Total time: 2943.73400 s
Total semisteps (function calls and closure unwraps): 2049664591
Mean semistep time: 1.436203 us

ApplyContraction-toExpr (3539) -> 159851984 (7.80 %, += 7.80 %)                     rel step time 1.65
Map@4 (2192) -> 130395652 (6.36 %, += 14.16 %)                                       rel step time 0.54
FilterPatternPos (2192) -> 129962587 (6.34 %, += 20.50 %)                            rel step time 0.88
Map@5 (2192) -> 124711616 (6.08 %, += 26.59 %)                                       rel step time 0.52
FilterResultPos (2192) -> 124278551 (6.06 %, += 32.65 %)                             rel step time 0.90
AllBrackets (6259) -> 76454677 (3.73 %, += 36.38 %)                                 rel step time 0.37
CheckHKRelation (6259) -> 55413420 (2.70 %, += 39.08 %)                             rel step time 4.26
CheckHKRelation-Term (6259) -> 52924360 (2.58 %, += 41.67 %)                        rel step time 0.69
CheckHKRelation$4?1 (6259) -> 52924360 (2.58 %, += 44.25 %)                         rel step time 0.74
CheckHKRelation$5?1 (6259) -> 52914029 (2.58 %, += 46.83 %)                         rel step time 0.71
__Step-Drop (0000) -> 37175383 (1.81 %, += 48.64 %)                                 rel step time 0.25
Map@14 (3539) -> 36309560 (1.77 %, += 50.41 %)                                      rel step time 0.82

_profile_count.txt

Профиль по времени:

Total time: 2943.73400 s
Total semisteps (function calls and closure unwraps): 2049664591
Mean semistep time: 1.436203 us

ApplyContraction-toExpr (3539) -> 379762.0 ms (12.90 %, += 12.90 %)                     rel step time 1.65
CheckHKRelation (6259) -> 338949.0 ms (11.51 %, += 24.41 %)                             rel step time 4.26
FilterPatternPos (2192) -> 165176.0 ms (5.61 %, += 30.03 %)                            rel step time 0.88
FilterResultPos (2192) -> 161168.0 ms (5.47 %, += 35.50 %)                             rel step time 0.90
Map@15 (1279) -> 143997.0 ms (4.89 %, += 40.39 %)                                      rel step time 8.51
Map@4 (2192) -> 101157.0 ms (3.44 %, += 43.83 %)                                       rel step time 0.54
Map@5 (2192) -> 92291.0 ms (3.14 %, += 46.96 %)                                       rel step time 0.52
Solve-Clashes (3539) -> 90715.0 ms (3.08 %, += 50.05 %)                               rel step time 7.78
CheckHKRelation$4?1 (6259) -> 55971.0 ms (1.90 %, += 51.95 %)                         rel step time 0.74
CheckHKRelation$5?1 (6259) -> 54060.0 ms (1.84 %, += 53.78 %)                         rel step time 0.71
CheckHKRelation-Term (6259) -> 52114.0 ms (1.77 %, += 55.55 %)                        rel step time 0.69
Map@14 (3539) -> 42890.0 ms (1.46 %, += 57.01 %)                                      rel step time 0.82
AllBrackets (6259) -> 40911.0 ms (1.39 %, += 58.40 %)                                 rel step time 0.37
Solve-Clashes$26=3@1 (3539) -> 40351.0 ms (1.37 %, += 59.77 %)                        rel step time 37.34
SimplifyCoordinates-Expr (3539) -> 36291.0 ms (1.23 %, += 61.00 %)                    rel step time 0.82

_profile_time.txt


Посмотрим ещё раз на счётчики:

ApplyContraction-toExpr (3539) -> 159851984 (7.80 %, += 7.80 %)                     rel step time 1.65
Map@4 (2192) -> 130395652 (6.36 %, += 14.16 %)                                       rel step time 0.54
FilterPatternPos (2192) -> 129962587 (6.34 %, += 20.50 %)                            rel step time 0.88
Map@5 (2192) -> 124711616 (6.08 %, += 26.59 %)                                       rel step time 0.52
FilterResultPos (2192) -> 124278551 (6.06 %, += 32.65 %)                             rel step time 0.90
AllBrackets (6259) -> 76454677 (3.73 %, += 36.38 %)                                 rel step time 0.37
  • Можно оптимизировать ApplyContraction-toExpr, откладывая применение сужений на самый последний момент. Но это даст не более 7,8 % от числа шагов.
  • Последующие четыре строчки — это back-end, его уже не оптимизируешь. Время его работы пропорционально объёму кода на входе. Стало быть, кода порождается слишком много (#332, #228).
  • Функция AllBrackets присутствует только в условиях. Её можно было бы раскрывать, разрешив прогонку без сужений внутри условий (#283).

Так что, по-видимому, основная проблема в распухании кода при оптимизациях (#332), либо в том, что оптимизируются функции, которые просто не вызываются (https://github.com/bmstu-iu9/refal-5-lambda/issues/228#issuecomment-714307025).

Mazdaywik avatar Jul 20 '21 16:07 Mazdaywik

Запускал компиляцию с выводом в лог:

set RLMAKE_FLAGS=-X-OiADS -X--log=__srefc-core.log

Основные выявленные проблемы:

  • [x] Не работает определение тривиальной сигнатуры. Проблема была известна ранее, но мы с @VladisP её оставили на потом. Аргумент имеет тривиальную сигнатуру, если он является жёстким выражением и все предложения специализируемой функции (за исключением неявного аварийного) являются его уточнениями. Замечу, что из этого определения непосредственно следует, что у пустой функции любой вызов имеет тривиальную сигнатуру. Примеров в коде много, приводить не буду.
  • [x] Не раскрываются вызовы замыканий.
    (e.Scanned) '\\r' e.Tail1
      = < {{DoUnEscapeString-SR-Escape$2:1@33
            (e.Scanned) (e.Tail1)
          }}
          Success '\r'
        >;
    
  • [ ] Ну, и проблема из https://github.com/bmstu-iu9/refal-5-lambda/issues/228#issuecomment-714307025.
  • [ ] Теперь порой проходит успешная специализация по некоторым совершенно случайным аргументам — это хорошо наблюдалось на Solve-Clashes. Нужен псевдокомментарий *$NOOPT (иначе придётся городить костыли с gen_e__), а для этого нужно делать #314.

Mazdaywik avatar Jul 20 '21 20:07 Mazdaywik

Возможно, стоит ослабить отношение Хигмана-Крускала:

    ResolveIncludes@1: [t.0 () (t.1 s.2 ((e.3) (e.3)) () e.4)]
    ResolveIncludes-CheckAlias@2: [t.0 () () ((t.1 s.2 ((e.3) (e.3)) (e.4 (Include t.5 e.6)) e.7)) () (e.6)]
    ResolveIncludes-CheckValid@3: [t.0 () () ((t.1 s.2 ((e.3) (e.3)) (e.4 (Include t.5 e.6)) e.7)) () (e.6) e.8]
    ResolveIncludes@5: [t.0 ((e.1)) (e.2 s.3 ((e.4) (e.4)) (e.5 (Include t.6 e.7)) e.8)]

Сопоставим @1 и @5:

    ResolveIncludes@1: [t.0 (     ) (t.1 s.2 ((e.3) (e.3)) (                     ) e.4)]
    ResolveIncludes@5: [t.0 ((e.1)) (e.2 s.3 ((e.4) (e.4)) (e.5 (Include t.6 e.7)) e.8)]

Если разрешить e-переменной поглощать другие переменные, то здесь произошло бы вложение.

Mazdaywik avatar Jul 21 '21 06:07 Mazdaywik

Сделана попытка исправить тривиальную сигнатуру, но она почему-то не работает. Обнаружены такие вызовы:

  Apply {
    s.Fn e.Argument = <__Meta_Mu s.Fn e.Argument &$table>;

    (t.Closure e.Bounded) e.Argument
      = <Apply@1 t.Closure e.Bounded e.Argument>;
  }
…
  Apply@1 {
    s.X0 e.X0 = <__Meta_Mu s.X0 e.X0 &$table>;

    (t.X1 e.X2) e.X0 = <Apply@1 t.X1 e.X2 e.X0>;

    t.X0 e.X0 = <Apply@0 t.X0 e.X0>;
  }
…
Thu Jul 22 00:58:57 2021: History of Apply@1
    Apply@0: [t.dyn0 e.STAT0]
    Apply@1: [t.0 e.1]

Сигнатура, очевидно, тривиальная. Более того, в истории она лежит (см. Apply@0)! Но вызов проспециализировался.


Обнаружена преждевременная специализация экземпляров:

Thu Jul 22 01:27:27 2021: History of PatchAST-Body$3\1=1@3
    GlueErrorListsAndASTs\1@0: [t.STAT0 (t.STAT1 (e.STAT0) e.STAT1)]
    Map@5: [(&PatchAST-Item {{&PatchASTSrcPos=1\1 "e.FileName:" (e.0)}}) e.1]
    PatchAST-Item@1: [{{&PatchASTSrcPos=1\1 "e.FileName:" (e.0)}} t.1]
    PatchAST-Body@2: [{{&PatchASTSrcPos=1\1 "e.FileName:" (e.0)}} e.1]
    Map@44: [(&PatchAST-Sentence {{&PatchASTSrcPos=1\1 "e.FileName:" (e.0)}}) e.1]
    PatchAST-Sentence@2: [{{&PatchASTSrcPos=1\1 "e.FileName:" (e.0)}} t.1]
    Map@67: [{{&PatchAST-Blocks\1 "s.FnPatch:" {{&PatchASTSrcPos=1\1 "e.FileName:" (e.0)}}}} e.1]
    PatchAST-Blocks\1@1: ["s.FnPatch:" {{&PatchASTSrcPos=1\1@3 (e.0)}} e.1]
    PatchAST-Body@4: [{{&PatchASTSrcPos=1\1@3 (e.0)}} e.1]
    PatchAST-Body$3\1@4: ["s.FnPatch:" {{&PatchASTSrcPos=1\1@3 (e.0)}} e.1]
    PatchAST-Body$3\1=1@3: ["e.Identifier:" (e.0) "s.FnPatch:" {{&PatchASTSrcPos=1\1@3 (e.1)}} "e.Name:" (e.2) e.3]

Thu Jul 22 01:27:27 2021: History of PatchAST-Body$3\1=1@4
    GlobalASTStorage-AddAST=3@0: ["s.NextLocalId:" s.STAT_NextLocalId "e.ASTs:" (e.STAT_ASTs) "e.AST$a:" (e.STAT_AST$a) "e.Inits:" (e.STAT_Inits) "e.Locals$a:" (e.STAT_Locals$a) "e.Finals:" (e.STAT_Finals) e.dyn]
    Map@14: [(&PatchAST-Item {{&GlobalASTStorage-AddAST=4\1 "e.Locals$a:" (e.0) "s.NextLocalId:" s.1}}) e.2]
    PatchAST-Item@3: [{{&GlobalASTStorage-AddAST=4\1 "e.Locals$a:" (e.0) "s.NextLocalId:" s.1}} t.2]
    PatchAST-Body@3: [{{&GlobalASTStorage-AddAST=4\1 "e.Locals$a:" (e.0) "s.NextLocalId:" s.1}} e.2]
    Map@46: [(&PatchAST-Sentence {{&GlobalASTStorage-AddAST=4\1 "e.Locals$a:" (e.0) "s.NextLocalId:" s.1}}) e.2]
    PatchAST-Sentence@3: [{{&GlobalASTStorage-AddAST=4\1 "e.Locals$a:" (e.0) "s.NextLocalId:" s.1}} t.2]
    Map@69: [{{&PatchAST-Blocks\1 "s.FnPatch:" {{&GlobalASTStorage-AddAST=4\1 "e.Locals$a:" (e.0) "s.NextLocalId:" s.1}}}} e.2]
    PatchAST-Blocks\1@2: ["s.FnPatch:" {{&GlobalASTStorage-AddAST=4\1@3 (e.0) s.1}} e.2]
    PatchAST-Body@5: [{{&GlobalASTStorage-AddAST=4\1@3 (e.0) s.1}} e.2]
    PatchAST-Body$3\1@5: ["s.FnPatch:" {{&GlobalASTStorage-AddAST=4\1@3 (e.0) s.1}} e.2]
    PatchAST-Body$3\1=1@4: ["e.Identifier:" (e.0) "s.FnPatch:" {{&GlobalASTStorage-AddAST=4\1@3 (e.1) s.2}} "e.Name:" (e.3) e.4]

См. PatchAST-Body@4 и PatchAST-Body@5.


Сильно распухает при компиляции Escape.ref. Раньше он так, вроде, не распухал.

Thu Jul 22 01:00:06 2021: History of DoUnEscapeString-SR-DecOct@98
    DoUnEscapeString-SR-Escape@0: [(e.STAT0) (e.dyn1) e.dyn2]
    DoUnEscapeString-SR@9: [(e.0 '\x0c') e.1]
    DoUnEscapeString-SR-DecOct@98: [(e.0 '\x0c') (8 '01234567') ('4') e.1]

Thu Jul 22 01:00:06 2021: History of DoUnEscapeString-SR-DecOct@99
    DoUnEscapeString-SR-Escape@0: [(e.STAT0) (e.dyn1) e.dyn2]
    DoUnEscapeString-SR@9: [(e.0 '\x0c') e.1]
    DoUnEscapeString-SR-DecOct@99: [(e.0 '\x0c') (8 '01234567') ('5') e.1]

Больше 99 экземпляров создать нельзя: https://github.com/bmstu-iu9/refal-5-lambda/blob/54c28cad9921556d208bc43dc88f55943d7885cb/src/compiler/OptTree-Spec.ref#L544-L551


  • [x] Исправить тривиальную сигнатуру.
  • [x] Понять, почему замыкание проспециализировалось раньше вызова функции с замыканием. И исправить.
  • [x] Понять, почему распухает Escape.ref, найти общие способы исправления проблемы. Потому что эта же проблема может быть и с другими файлами.

Mazdaywik avatar Jul 21 '21 23:07 Mazdaywik

Запустил компиляцию в режиме

set RLMAKE_FLAGS=-X-OiADS

Компилятор ожидаемо вылетел:

…
*Compiling Desugaring-UnCondition.ref:
*Compiling Checker-Screening.ref:
*Compiling ObjectMatch.ref:
*Compiling GlobalGen.ref:
*Compiling R5-Lexer.ref:
*Compiling R5-Parser.ref:
*Compiling SR-Lexer.sref:
*Compiling SR-Parser.sref:

STEP LIMIT REACHED (2000000000)


Total program time: 4034.95300 seconds (100.0 %).
(Total refal time): 3218.22500 seconds (79.8 %).
t- and e-var copy time: 933.16800 seconds (23.1 %).
Linear pattern time: 811.13200 seconds (20.1 %).
Open e-loop time (clear): 746.61700 seconds (18.5 %).
Runtime time overhead: 735.50900 seconds (18.2 %).
Linear result time: 545.05600 seconds (13.5 %).
Repeated t-var match time (inside e-loops): 116.49300 seconds (2.9 %).
Native time: 79.76400 seconds (2.0 %).
Repeated e-var match time (inside e-loops): 51.35100 seconds (1.3 %).
Repeated t-var match time (outside e-loops): 8.29500 seconds (0.2 %).
Repeated e-var match time (outside e-loops): 6.11300 seconds (0.2 %).
Context copy time: 1.45500 seconds (0.0 %).

Интересны профили. Профиль по числу шагов (отсечка 50 %):

Total time: 4030.84400 s
Total semisteps (function calls and closure unwraps): 2014556460
Mean semistep time: 2.000859 us

ApplyContraction-toExpr (9049) -> 236764271 (11.75 %, += 11.75 %)                     rel step time 1.38
Map@14 (9049) -> 63372999 (3.15 %, += 14.90 %)                                      rel step time 0.68
__Step-Drop (0000) -> 62391441 (3.10 %, += 18.00 %)                                 rel step time 0.22
AllBrackets (6259) -> 59410059 (2.95 %, += 20.94 %)                                 rel step time 0.32
ApplyContraction-toContraction (9049) -> 56213951 (2.79 %, += 23.73 %)              rel step time 0.47
SimplifyCoordinates-Expr (9049) -> 52721047 (2.62 %, += 26.35 %)                    rel step time 0.68
ExtractVariables-Expr (0000) -> 43388383 (2.15 %, += 28.51 %)                       rel step time 0.56
ClearCoordinates (9049) -> 43230956 (2.15 %, += 30.65 %)                            rel step time 0.63
CheckHKRelation (6259) -> 43043928 (2.14 %, += 32.79 %)                             rel step time 7.52
Map@10 (9049) -> 40017966 (1.99 %, += 34.77 %)                                      rel step time 0.42
CheckHKRelation-Term (6259) -> 39947222 (1.98 %, += 36.76 %)                        rel step time 0.61
CheckHKRelation$4?1 (6259) -> 39947222 (1.98 %, += 38.74 %)                         rel step time 0.66
CheckHKRelation$5?1 (6259) -> 39929262 (1.98 %, += 40.72 %)                         rel step time 0.66
Map@16 (9049) -> 39687193 (1.97 %, += 42.69 %)                                      rel step time 0.62
SimplifyCoordinates-Assign (9049) -> 32257990 (1.60 %, += 44.29 %)                  rel step time 0.43
ApplyContraction-toAssign (9049) -> 32257990 (1.60 %, += 45.90 %)                   rel step time 0.49
Add (0000) -> 22508379 (1.12 %, += 47.01 %)                                         rel step time 0.57
Add-Digits (7068) -> 22458422 (1.11 %, += 48.13 %)                                  rel step time 0.21
Map@9 (9049) -> 22167775 (1.10 %, += 49.23 %)                                       rel step time 0.41
Map@15 (9049) -> 22058444 (1.09 %, += 50.32 %)                                      rel step time 0.61

_profile_count.txt

Профиль по времени (отсечка 50 %):

Total time: 4030.84400 s
Total semisteps (function calls and closure unwraps): 2014556460
Mean semistep time: 2.000859 us

ApplyContraction-toExpr (9049) -> 654226.0 ms (16.23 %, += 16.23 %)                     rel step time 1.38
CheckHKRelation (6259) -> 647448.0 ms (16.06 %, += 32.29 %)                             rel step time 7.52
Solve-Clashes (9049) -> 253750.0 ms (6.30 %, += 38.59 %)                               rel step time 6.61
Map@14 (9049) -> 86573.0 ms (2.15 %, += 40.74 %)                                      rel step time 0.68
SimplifyCoordinates-Expr (9049) -> 71826.0 ms (1.78 %, += 42.52 %)                    rel step time 0.68
Solve-Clashes$26=3@1 (9049) -> 65514.0 ms (1.63 %, += 44.14 %)                        rel step time 18.25
Unique (0000) -> 55258.0 ms (1.37 %, += 45.51 %)                                      rel step time 4.31
ClearCoordinates (9049) -> 54904.0 ms (1.36 %, += 46.88 %)                            rel step time 0.63
CheckHKRelation$4?1 (6259) -> 52930.0 ms (1.31 %, += 48.19 %)                         rel step time 0.66
CheckHKRelation$5?1 (6259) -> 52669.0 ms (1.31 %, += 49.50 %)                         rel step time 0.66
ApplyContraction-toContraction (9049) -> 52656.0 ms (1.31 %, += 50.80 %)              rel step time 0.47

_profile_time.txt

На что надо обратить внимание:

  • ApplyContraction-toExpr — всё-таки нужно делать отложенное применение сужений. Из тройки ‹сужения, клэши, присваивания› на каждой итерации нужно применять сужения только ко второму компоненту (сейчас они применяются ко всем, что делает набор сужений параллельным). Тогда набор сужений будет последовательным, а сужения к присваиваниям будут применяться только при переходе к симметричным клэшам.
  • Функция Map@14 (9049), она на втором месте по числу шагов и на четвёртом по времени. Это вот этот вызов: https://github.com/bmstu-iu9/refal-5-lambda/blob/49c506138304131862ae0b8d266c28dc9a419069/src/compiler/GenericMatch.ref#L2171-L2175 Опять же, при переходе к последовательным сужениям этого вызова не будет.
  • Неожиданно всплыло отношение Хигмана-Крускала:
    CheckHKRelation (6259) -> 647448.0 ms (16.06 %, += 32.29 %)                             rel step time 7.52
    
  • Map@10 (9049) — это <Map &SimplifyCoordinates-Assign e.Assigns>: https://github.com/bmstu-iu9/refal-5-lambda/blob/49c506138304131862ae0b8d266c28dc9a419069/src/compiler/GenericMatch.ref#L444-L449 Этот вызов вообще не нужен. Во-первых, скопления координат в присваиваниях могут возникнуть только при стирающих подстановках. Во-вторых, координаты в присваиваниях нужны только при решении симметричных клэшей, поэтому имеет смысл их упрощать только при переходе к этому этапу. В-третьих, как сказано выше, применять сужения к присваиваниям раньше времени не нужно.
  • Map@16 (9049) — это <Map (&ApplyContraction-toAssign t.toAdd) e.Assigns>: https://github.com/bmstu-iu9/refal-5-lambda/blob/49c506138304131862ae0b8d266c28dc9a419069/src/compiler/GenericMatch.ref#L2171-L2178 Опять же, не нужна.

Выводы:

  • [x] Сужения нужно делать последовательными, их применение к присваиваниям откладывать.
  • [x] Попробовать предварить отношение Хигмана-Крускала отношением Хигмана. Отношение Хигмана для двух выражений как последовательностей токенов проверяется за линейное время, если не выполняется отношение Хигмана, то заведомо не выполнится отношение Хигмана-Крускала.

Mazdaywik avatar Jul 23 '21 06:07 Mazdaywik

Выяснил, откуда появились сигнатуры вида

PatchAST-Blocks\1@1: ["s.FnPatch:" {{&PatchASTSrcPos=1\1@3 (e.0)}} e.1]

Т.е. когда внутри сигнатуры появляется проспециализированное замыкание.

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

А сигнатуры берутся вот откуда. Код на одном из проходов специализации:

        <Map
          {{PatchAST-Blocks\1
            "s.FnPatch:" {{&PatchASTSrcPos=1\1 "e.FileName:" (e.UnitName)}}
          }}
          e.AST9
        >;

И он специализируется, внимание, в

        <Map {{&PatchAST-Blocks\1@1 (e.UnitName)}} e.AST9>;

Обход выражения происходит изнутри наружу, т.е. сначала специализируется {{&PatchASTSrcPos=1\1 …}}, а потом специализируется {{PatchAST-Blocks\1 … }}. Из-за чего внешнее замыкание специализируется по специализированному экземпляру внутреннего!

Но почему же не специализируется Map? Потому что уже есть 99 экземпляров Map:

    Map@7: [{{&PatchAST-Expr\1 "s.FnPatch:" s.0}} e.1]
    Map@80: [&ResolveIncludes$3\1 (e.0 s.1 (e.2) (e.3 (Include t.4 e.5 (Include t.6 e.7))) e.8)]
    Map@81: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 (Include t.7 e.3)) e.8 s.9 (e.10) (e.11 s.12 ((e.13) (e.13)) (Include t.14 e.15 (Include t.16 e.17))) e.18)) ()]
    Map@82: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 s.7 (Include t.8 e.3)) (e.9 s.10 ((e.11) (e.11)) (Include t.12 e.13 (Include t.14 e.15))) e.16)) ()]
    Map@83: [&UnBracket () ((t.0 s.1 (e.2 (e.3 s.4 ((e.5) (e.5)) (Include t.6 e.7 (Include t.8 e.9))) e.10) (e.11 e.12 s.13 (e.14) (Include t.15 e.3 s.4 ((e.5) (e.5)) (Include t.6 e.7 (Include t.8 e.9)))) e.16)) ()]
    Map@84: [&UnBracket () ((t.0 s.1 (e.2 (((e.3) (e.3)) (Include t.4 e.5 (Include t.6 e.7))) e.8) (e.9 e.10 s.11 (e.12) (Include s.13 ((e.3) (e.3)) (Include t.4 e.5 (Include t.6 e.7)))) e.14)) ()]
    Map@85: [&UnBracket () ((t.0 s.1 (e.2 ((Include t.3 e.4 (Include t.5 e.6))) e.7) (e.8 e.9 s.10 (e.11) (Include ((e.12) (e.12)) (Include t.3 e.4 (Include t.5 e.6)))) e.13)) ()]
    Map@86: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 s.7 (e.8) (e.9 s.10 ((e.11) (e.11)) (Include t.12 e.13 (Include t.14 e.15))) e.16 (Include t.17 e.3)) e.18)) ()]
    Map@87: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 s.6 ((e.7) (e.7)) (Include t.8 e.9 (Include t.10 e.11)) e.12 (Include t.13 e.3)) e.14)) ()]
    Map@88: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 (Include t.7 e.3)) e.8 s.9 (e.10) (e.11 e.12 s.13 ((e.14) (e.14)) (Include (Include t.15 e.16))) e.17)) ()]
    Map@89: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 s.7 (Include t.8 e.3)) (e.9 e.10 s.11 ((e.12) (e.12)) (Include (Include t.13 e.14))) e.15)) ()]
    Map@8: [(&PatchAST-Sentence s.0) e.1]
    Map@90: [&UnBracket () ((t.0 s.1 (e.2 (e.3 s.4 ((e.5) (e.5)) (Include (Include t.6 e.7))) e.8) (e.9 e.10 s.11 (e.12) (Include t.13 e.14 e.15 s.4 ((e.5) (e.5)) (Include (Include t.6 e.7)))) e.16)) ()]
    Map@91: [&UnBracket () ((t.0 s.1 (e.2 (e.3 s.4 ((e.5) (e.5)) (Include (Include t.6 e.7))) e.8) (e.9 e.10 s.11 (e.12) (Include t.13 e.3 s.4 ((e.5) (e.5)) (Include (Include t.6 e.7)))) e.14)) ()]
    Map@92: [&UnBracket () ((t.0 s.1 (e.2 (((e.3) (e.3)) (Include (Include t.4 e.5))) e.6) (e.7 e.8 s.9 (e.10) (Include s.11 ((e.3) (e.3)) (Include (Include t.4 e.5)))) e.12)) ()]
    Map@93: [&UnBracket () ((t.0 s.1 (e.2 ((Include (Include t.3 e.4))) e.5) (e.6 e.7 s.8 (e.9) (Include ((e.10) (e.10)) (Include (Include t.3 e.4)))) e.11)) ()]
    Map@94: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 s.7 (e.8) (e.9 e.10 s.11 ((e.12) (e.12)) (Include (Include t.13 e.14))) e.15 (Include t.16 e.3)) e.17)) ()]
    Map@95: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 s.7 ((e.8) (e.8)) (Include (Include t.9 e.10)) e.11 (Include t.12 e.3)) e.13)) ()]
    Map@96: [&ResolveIncludes$3\1 (e.0 s.1 (e.2) (e.3 e.4 s.5 (e.6) (Include (Include t.7 e.8))) e.9)]
    Map@97: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 (Include t.7 e.3)) e.8 s.9 (e.10) (e.11 (Include t.12 e.13)) e.14)) ()]
    Map@98: [&UnBracket () ((t.0 s.1 (e.2 (e.3) e.4) (e.5 e.6 s.7 (Include t.8 e.3)) (e.9 (Include t.10 e.11)) e.12)) ()]
    Map@99: [&UnBracket () ((t.0 s.1 (e.2 (e.3 (Include t.4 e.5)) e.6) (e.7 e.8 s.9 (e.10) (Include t.11 e.3 (Include t.4 e.5))) e.12)) ()]
    Map@9: [{{&PatchAST-Body$3\1 "s.FnPatch:" s.0}} e.1]

Большинство экземпляров функции Map на самом можно вычислить во время компиляции.

Поэтому два вывода:

  • [x] Специализировать выражение надо снаружи внутрь. Порядок специализации для вызовов функций значения не имеет — в любом случае вызов функции заменяется на фиктивную e-переменную, потом снова она заменяется на вызов, порядок сохраняется. Для замыканий это принципиально. При этом, если специализировать снаружи внутрь, можно обойтись без двух отдельных проходов — всё специализироваться будет правильно.
  • [x] Функции Map (и, возможно, некоторым другим) нужно добавить метку $INLINE.

Mazdaywik avatar Jul 23 '21 18:07 Mazdaywik

Купировал бо́льшую часть распуханий. Перезапустил компиляцию с ключами

set RLMAKE_FLAGS=-X-OiADS

Компилятор вылетел уже так:

…
*Compiling HighLevelRASL-GenSubst-Save.ref:
*Compiling HighLevelRASL-ConjointFunc.ref:
*Compiling HighLevelRASL-GenSubst-Simple.ref:

STEP LIMIT REACHED (2000000000)


Total program time: 3345.17200 seconds (100.0 %).
(Total refal time): 2536.63400 seconds (75.8 %).
Linear pattern time: 751.68200 seconds (22.5 %).
Runtime time overhead: 720.49900 seconds (21.5 %).
Open e-loop time (clear): 645.42100 seconds (19.3 %).
Linear result time: 519.58500 seconds (15.5 %).
t- and e-var copy time: 450.60800 seconds (13.5 %).
Repeated t-var match time (inside e-loops): 121.24600 seconds (3.6 %).
Native time: 86.34600 seconds (2.6 %).
…

что не может не радовать. До самоприменения в этом режиме уже недалеко.

Профиль по числу шагов (отсечка 50 %):

Total time: 3344.17200 s
Total semisteps (function calls and closure unwraps): 2009279991
Mean semistep time: 1.664363 us

ApplyContraction-toExpr (3084) -> 235464077 (11.72 %, += 11.72 %)                     rel step time 1.67
Map@14 (3084) -> 68955530 (3.43 %, += 15.15 %)                                      rel step time 0.84
__Step-Drop (0000) -> 64741936 (3.22 %, += 18.37 %)                                 rel step time 0.26
ApplyContraction-toContraction (3084) -> 61948630 (3.08 %, += 21.46 %)              rel step time 0.59
SimplifyCoordinates-Expr (3084) -> 54306557 (2.70 %, += 24.16 %)                    rel step time 0.81
Map@2 (0206) -> 51281938 (2.55 %, += 26.71 %)                                       rel step time 0.68
Map@10 (3084) -> 43671768 (2.17 %, += 28.88 %)                                      rel step time 0.50
Map@16 (3084) -> 43178224 (2.15 %, += 31.03 %)                                      rel step time 0.77
ExtractVariables-Expr (0000) -> 40121535 (2.00 %, += 33.03 %)                       rel step time 0.64
SimplifyCoordinates-Assign (3084) -> 35787814 (1.78 %, += 34.81 %)                  rel step time 0.51
ApplyContraction-toAssign (3084) -> 35787814 (1.78 %, += 36.59 %)                   rel step time 0.58
ClearCoordinates (3084) -> 31711646 (1.58 %, += 38.17 %)                            rel step time 0.76
Map@9 (3084) -> 21717947 (1.08 %, += 39.25 %)                                       rel step time 0.49
Map@15 (3084) -> 21544874 (1.07 %, += 40.32 %)                                      rel step time 0.72
Add (0000) -> 21443577 (1.07 %, += 41.39 %)                                         rel step time 0.68
Add-Digits (3087) -> 21399594 (1.07 %, += 42.46 %)                                  rel step time 0.25
Type (0000) -> 20958574 (1.04 %, += 43.50 %)                                        rel step time 0.26
IsTerm (3084) -> 20826037 (1.04 %, += 44.54 %)                                      rel step time 0.65
gen_e__ (3084) -> 19918790 (0.99 %, += 45.53 %)                                     rel step time 0.41
InlineTerm (9684) -> 19834943 (0.99 %, += 46.51 %)                                  rel step time 0.54
DoInlineExpr (9684) -> 19834943 (0.99 %, += 47.50 %)                                rel step time 0.63
Map@3 (0206) -> 19308587 (0.96 %, += 48.46 %)                                       rel step time 0.52
Divmod-Digits (3087) -> 19303190 (0.96 %, += 49.42 %)                               rel step time 0.26
Solve-Clashes (3084) -> 19073587 (0.95 %, += 50.37 %)                               rel step time 7.34

_profile_count.txt

Профиль по времени (отсечка 50 %):

Total time: 3344.17200 s
Total semisteps (function calls and closure unwraps): 2009279991
Mean semistep time: 1.664363 us

ApplyContraction-toExpr (3084) -> 654005.0 ms (19.56 %, += 19.56 %)                     rel step time 1.67
Solve-Clashes (3084) -> 233098.0 ms (6.97 %, += 26.53 %)                               rel step time 7.34
Solve-Clashes$26=3@1 (3084) -> 103212.0 ms (3.09 %, += 29.61 %)                        rel step time 30.53
Map@14 (3084) -> 95898.0 ms (2.87 %, += 32.48 %)                                      rel step time 0.84
SimplifyCoordinates-Expr (3084) -> 73064.0 ms (2.18 %, += 34.67 %)                    rel step time 0.81
ApplyContraction-toContraction (3084) -> 61293.0 ms (1.83 %, += 36.50 %)              rel step time 0.59
Map@2 (0206) -> 58342.0 ms (1.74 %, += 38.24 %)                                       rel step time 0.68
Map@16 (3084) -> 55651.0 ms (1.66 %, += 39.91 %)                                      rel step time 0.77
ExtractVariables-Expr (0000) -> 42968.0 ms (1.28 %, += 41.19 %)                       rel step time 0.64
DoGenSubst (4402) -> 42947.0 ms (1.28 %, += 42.48 %)                                  rel step time 18.81
Unique (0000) -> 42555.0 ms (1.27 %, += 43.75 %)                                      rel step time 4.10
ClearCoordinates (3084) -> 39850.0 ms (1.19 %, += 44.94 %)                            rel step time 0.76
AddContraction-Spec (3084) -> 37637.0 ms (1.13 %, += 46.07 %)                         rel step time 2.91
Map@10 (3084) -> 36247.0 ms (1.08 %, += 47.15 %)                                      rel step time 0.50
ApplyContraction-toAssign (3084) -> 34602.0 ms (1.03 %, += 48.18 %)                   rel step time 0.58
NewVarName (0000) -> 33749.0 ms (1.01 %, += 49.19 %)                                  rel step time 2.98
DoNewVarName:1@2 (6184) -> 33738.0 ms (1.01 %, += 50.20 %)                            rel step time 3.30
Solve-Clashes$26?1 (3084) -> 30575.0 ms (0.91 %, += 51.12 %)                          rel step time 7.69

_profile_time.txt

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

Mazdaywik avatar Jul 24 '21 09:07 Mazdaywik

Не все функции прогоняются

В логе замечены следующие экземпляры:

…
    AddContraction-Spec@30: [((Var 't' e.0) ':' (ADT-Brackets (e.1) (Var 'e' e.2))) (e.3) e.4 ((('{' s.5 '}') (Var 't' e.0) ('{' s.6 '}')) ':' ((ADT-Brackets (e.1) e.7))) e.8 ((e.9) ':' (e.10)) e.11 (e.12)]
    AddContraction-Spec@31: [((Var 't' e.0) ':' (ADT-Brackets (e.1) (Var 'e' e.2))) (e.3) e.4 ((e.5) ':' (e.6)) e.7 ((('{' s.8 '}') (Var 't' e.0) ('{' s.9 '}')) ':' ((ADT-Brackets (e.1) e.10))) e.11 (e.12)]
    AddContraction-Spec@32: [((Var 't' e.0) ':' (Var 's' e.1)) (e.2) e.3 ((('{' s.4 '}') (Var 't' e.0) ('{' s.5 '}')) ':' (t.6)) e.7 ((e.8) ':' (e.9)) e.10 (e.11)]
    AddContraction-Spec@33: [((Var 't' e.0) ':' (Var 's' e.1)) (e.2) e.3 ((e.4) ':' (e.5)) e.6 ((('{' s.7 '}') (Var 't' e.0) ('{' s.8 '}')) ':' (t.9)) e.10 (e.11)]
    AddContraction-Spec@34: [((Var 'e' e.0) ':') (None e.1) e.2 ()]
    AddContraction-Spec@35: [((Var 'e' e.0) ':' (Var 't' e.1) (Var 'e' e.2)) (None e.3) e.4 (e.5)]
    AddContraction-Spec@36: [((Var 'e' e.0) ':' (Var 'e' e.1) (Var 't' e.2)) (None e.3) e.4 (e.5)]
    AddContraction-Spec@37: [(t.0 ':' (Var 'e' e.1) (Var 'e' e.2)) (None e.3) e.4 (e.5)]
    AddContraction-Spec@38: [((Var 'e' e.0) ':') (None e.1) e.2 (e.3)]
    AddContraction-Spec@39: [(t.0 ':' (Var 'e' e.1) (Var 't' e.2) (Var 'e' e.3)) (None e.4) e.5 (e.6)]
    AddContraction-Spec@3: [((Var 't' e.0) ':' (Var 's' e.1)) (e.2) e.3 ((('{' s.4 '}') (Var 't' e.0) ('{' s.5 '}')) ':' (t.6)) e.7 (e.8)]
    AddContraction-Spec@4: [((Var 'e' e.0) ':') (e.1) e.2 (e.3)]
    AddContraction-Spec@5: [((Var 'e' e.0) ':' (Var 't' e.1) (Var 'e' e.2)) (e.3) e.4 (e.5)]
    AddContraction-Spec@6: [((Var 'e' e.0) ':' (Var 'e' e.1) (Var 't' e.2)) (e.3) e.4 (e.5)]
    AddContraction-Spec@7: [((Var 's' e.0) ':' (Symbol s.1 e.2)) (e.3) e.4 ((('{' s.5 '}') (Var 's' e.0) ('{' s.6 '}')) ':' ((Symbol s.1 e.2))) e.7 (e.8)]
    AddContraction-Spec@8: [((Var 'e' e.0) ':') (e.1) e.2 ((('{' s.3 '}') (Var 'e' e.0) e.4 ('{' s.5 '}')) ':' ()) e.6 (e.7)]
    AddContraction-Spec@9: [(t.0 ':' t.1 t.2 t.3) (e.4) e.5 (e.6)]
…
    ReportErrors@20: [CommandLine t.0 (1 'Option --no-sources require option -o (--target-file)')]
    ReportErrors@21: [(e.0) t.1 (1 'option -x (or --exe) require option --cpp-command-exe with nonempty value')]
    ReportErrors@22: [(e.0) t.1 (1 'unexpected native file ' e.2 ' while compilation runs with prefix')]
    ReportErrors@23: [(e.0) t.1 (1 'option -l (or --lib) with native code require option --cpp-command-lib with nonempty value')]
    ReportErrors@24: [(e.0) t.1 (1 'unexpected native file ' e.2 ' while creating R module')]
    ReportErrors@25: [CommandLine t.0 (1 'option -x (or --exe) require option --cpp-command-exe with nonempty value')]
    ReportErrors@26: [CommandLine t.0 (1 'unexpected native file ' e.1 ' while compilation runs with prefix')]
    ReportErrors@27: [CommandLine t.0 (1 'option -l (or --lib) with native code require option --cpp-command-lib with nonempty value')]
    ReportErrors@28: [CommandLine t.0 (1 'unexpected native file ' e.1 ' while creating R module')]
    ReportErrors@29: [(e.0) t.1 (1 'Can\'t find prefix ' e.2)]
    ReportErrors@2: [t.0 NoConfig e.1]
    ReportErrors@30: [CommandLine t.0 (1 'Can\'t find prefix ' e.1)]
    ReportErrors@3: [t.0 t.1 (s.2 'file ' e.3 ' is not found') e.4]
    ReportErrors@4: [t.0 t.1 (1 'Option --no-sources require option -o (--target-file)')]
    ReportErrors@5: [t.0 t.1 e.2 e.3]
    ReportErrors@6: [t.0 t.1 (1 'Can\'t find prefix ' e.2)]
    ReportErrors@7: [t.0 t.1 (1 'option -x (or --exe) require option --cpp-command-exe with nonempty value')]
    ReportErrors@8: [t.0 t.1 (1 'unexpected native file ' e.2 ' while compilation runs with prefix')]
    ReportErrors@9: [t.0 t.1 (1 'option -l (or --lib) with native code require option --cpp-command-lib with nonempty value')]
…
    ReportMessages@30: [(&OnWarnings 'Warning') (e.0) t.1 (1 'Can\'t find prefix ' e.2 ', create module without prefix (R module)')]
    ReportMessages@31: [(&OnErrors 'Error') (e.0) t.1 (1 'unexpected native file ' e.2 ' while creating R module')]
    ReportMessages@32: [(&OnErrors 'Error') CommandLine t.0 (1 'option -x (or --exe) require option --cpp-command-exe with nonempty value')]
    ReportMessages@33: [(&OnErrors 'Error') CommandLine t.0 (1 'unexpected native file ' e.1 ' while compilation runs with prefix')]
    ReportMessages@34: [(&OnErrors 'Error') CommandLine t.0 (1 'option -l (or --lib) with native code require option --cpp-command-lib with nonempty value')]
    ReportMessages@35: [(&OnWarnings 'Warning') CommandLine t.0 (1 'Can\'t find prefix ' e.1 ', create module without prefix (R module)')]
    ReportMessages@36: [(&OnErrors 'Error') CommandLine t.0 (1 'unexpected native file ' e.1 ' while creating R module')]
    ReportMessages@37: [(&OnErrors 'Error') (e.0) t.1 (1 'Can\'t find prefix ' e.2)]
    ReportMessages@38: [(&OnErrors 'Error') CommandLine t.0 (1 'Can\'t find prefix ' e.1)]
    ReportMessages@3: [(&OnWarnings 'Warning') t.0 t.1 (1 'Can\'t find prefix ' e.2 ', create module without prefix (R module)')]
    ReportMessages@4: [(&OnWarnings 'Warning') t.0 t.1 (1 'prefix name or C++ command line is not found, create library without prefix')]
    ReportMessages@5: [(&OnErrors 'Error') t.0 t.1 (1 'no source files in command line')]
    ReportMessages@6: [(&OnErrors 'Error') t.0 NoConfig e.1]
    ReportMessages@7: [(&OnErrors 'Error') t.0 t.1 (s.2 'file ' e.3 ' is not found') e.4]
    ReportMessages@8: [(&OnErrors 'Error') t.0 t.1 (1 'Option --no-sources require option -o (--target-file)')]
    ReportMessages@9: [(&OnErrors 'Error') t.0 t.1 e.2 e.3]

И это странно. Данные функции достаточно простые и нерекурсивные, чтобы их можно было прогнать в режиме -OA+.


Почему-то авторазметка не помечает их для прогонки.


Разгадка в том, что эти функции вызывают MapApplyMu$table и таким образом цикл замыкается.

Mazdaywik avatar Jul 24 '21 14:07 Mazdaywik

Теперь удалось самоприменить компилятор с ключами

set RLMAKE_FLAGS=-X-OiADS

Компиляция с ключами

set RLMAKE_FLAGS=-X-OiADPRS

пока прерывается по лимиту шагов.

Mazdaywik avatar Jul 30 '21 13:07 Mazdaywik

Комментарий не сворачивать, на него ссылка из https://github.com/bmstu-iu9/refal-5-lambda/issues/332#issuecomment-890483185.

Часто формируются сигнатуры, содержащие «открытые переменные» e.1 … e.2, и эти сигнатуры, как правило, довольно бессодержательны.

    Block@10: [t.0 Classic (TkOpenBlock t.1) e.2 (e.3 (Symbol Number Cookie1) (Symbol Number Cookie2)) e.4]
    Block@11: [t.0 s.1 (TkOpenBlock t.2) e.3 (e.4 (Symbol Number Cookie1) (Symbol Number Cookie2)) e.5]
    Block@12: [t.0 s.1 (TkOpenBlock t.2) e.3 (e.4) e.5]
    Block@13: [t.0 s.1 (TkOpenBlock t.2) e.3 (e.4 (Brackets e.5 e.6)) e.7]
    Block@14: [t.0 s.1 (TkOpenBlock (Brackets e.2 e.3)) e.4]
    Block@15: [t.0 s.1 (TkOpenBlock t.2) e.3 (e.4 (CallBrackets e.5 e.6)) (s.7 t.8 e.9) e.10]
    Block@16: [t.0 s.1 (TkOpenBlock (CallBrackets e.2 e.3)) (s.4 t.5 e.6) e.7]
    Block@17: [t.0 s.1 e.2 s.3 (e.4) e.5]
    Block@18: [t.0 s.1 (TkOpenBlock t.2) e.3 (s.4 t.5 e.6) e.7]
    Block@19: [t.0 s.1 (TkOpenBlock t.2) e.3 (e.4 (Brackets e.5)) e.6]
    Block@1: [t.0 s.1 e.2]
    Block@20: [t.0 s.1 (TkOpenBlock (Brackets e.2)) e.3]
    Block@21: [t.0 s.1 (TkOpenBlock t.2) e.3 (e.4 (CallBrackets e.5)) (s.6 t.7 e.8) e.9]
    Block@22: [t.0 s.1 (TkOpenBlock (CallBrackets e.2)) (s.3 t.4 e.5) e.6]
    Block@23: [t.0 s.1 (TkOpenBlock t.2) e.3 (e.4 (Brackets (Symbol Name t.5 e.6) e.7)) e.8]
    Block@2: [t.0 s.1 (TkOpenBlock t.2) e.3]
    Block@3: [t.0 Extended e.1]
    Block@4: [t.0 Extended (TkOpenBlock t.1) e.2]
    Block@5: [t.0 Classic (TkOpenBlock t.1) e.2 e.3]
    Block@6: [t.0 Classic (TkOpenBlock t.1) e.2]
    Block@7: [t.0 Extended (TkOpenBlock t.1) e.2 (e.3) e.4]
    Block@8: [t.0 Extended (TkOpenBlock t.1) e.2 e.3]
    Block@9: [t.0 s.1 (TkOpenBlock t.2) e.3 e.4]
    Expression@0: [t.STAT0 s.STAT0 s.STAT1 e.STAT0]
    Expression@10: [t.0 s.1 Pattern e.2 s.3 (e.4 e.5) e.6]
    Expression@11: [t.0 Classic Pattern e.1 e.2]
    Expression@12: [t.0 Classic Pattern e.1]
    Expression@13: [t.0 Extended Pattern e.1 (e.2) e.3]
    Expression@14: [t.0 Extended Pattern e.1 e.2]
    Expression@15: [t.0 s.1 Pattern e.2 e.3]
    Expression@16: [t.0 Classic Pattern e.1 (e.2 (Symbol Number Cookie1) (Symbol Number Cookie2)) e.3]
    Expression@17: [t.0 s.1 Pattern e.2 (e.3 (Symbol Number Cookie1) (Symbol Number Cookie2)) e.4]
    Expression@18: [t.0 s.1 Pattern e.2 (e.3) e.4]
    Expression@19: [t.0 s.1 Pattern e.2 (e.3 (Brackets e.4 e.5)) e.6]
    …

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

  • [x] Обобщать участки между двумя e-параметрами.

Mazdaywik avatar Jul 31 '21 16:07 Mazdaywik

В логе увидел вот такую странную картину:

Sun Aug 01 00:37:26 2021: History of DoTokenChain:1$7=1@19
    DoTokenChain:1@0: ["s.Mode:" s.STAT_Mode "s.Kind:" s.STAT_Kind "t.ErrorList:" t.STAT_ErrorList "e.Collected:" (e.STAT_Collected) "e.Tokens:" (e.STAT_Tokens) e.dyn]
    DoTokenChain@9: [s.0 s.1 t.2 (e.3 (Symbol Char s.4)) e.5]
    DoTokenChain:1$7=1@19: ["s.Mode:" s.0 "s.Kind:" s.1 "t.Pos:" t.2 "e.Tokens:" (e.3) "e.Collected:" (e.4 (Symbol Char s.5)) e.6]

Sun Aug 01 00:37:26 2021: History of DoTokenChain:1$9=1@18
    DoTokenChain:1@0: ["s.Mode:" s.STAT_Mode "s.Kind:" s.STAT_Kind "t.ErrorList:" t.STAT_ErrorList "e.Collected:" (e.STAT_Collected) "e.Tokens:" (e.STAT_Tokens) e.dyn]
    DoTokenChain@9: [s.0 s.1 t.2 (e.3 (Symbol Char s.4)) e.5]
    DoTokenChain:1$9=1@18: ["s.Mode:" Classic "s.Kind:" s.0 "e.Collected:" (e.1 (Symbol Char s.2)) "t.OpenPos:" t.3 "e.FuncName:" (e.4) "e.Tokens:" (e.5) e.6]

Sun Aug 01 00:37:26 2021: History of DoTokenChain:1$9=2@10
    DoTokenChain:1@0: ["s.Mode:" s.STAT_Mode "s.Kind:" s.STAT_Kind "t.ErrorList:" t.STAT_ErrorList "e.Collected:" (e.STAT_Collected) "e.Tokens:" (e.STAT_Tokens) e.dyn]
    DoTokenChain@9: [s.0 s.1 t.2 (e.3 (Symbol Char s.4)) e.5]
    DoTokenChain:1$9=2@10: ["s.Mode:" Extended "s.Kind:" s.0 "e.Collected:" (e.1 (Symbol Char s.2)) "t.OpenPos:" t.3 "e.FuncName:" (e.4) e.5]

Sun Aug 01 00:37:26 2021: History of DoTokenChain:1$9=1@19
    DoTokenChain:1@0: ["s.Mode:" s.STAT_Mode "s.Kind:" s.STAT_Kind "t.ErrorList:" t.STAT_ErrorList "e.Collected:" (e.STAT_Collected) "e.Tokens:" (e.STAT_Tokens) e.dyn]
    DoTokenChain@9: [s.0 s.1 t.2 (e.3 (Symbol Char s.4)) e.5]
    DoTokenChain:1$9=1@19: ["s.Mode:" s.0 "s.Kind:" s.1 "e.Collected:" (e.2 (Symbol Char s.3)) "t.OpenPos:" t.4 "e.FuncName:" (e.5) "e.Tokens:" (e.6) e.7]

Sun Aug 01 00:37:26 2021: History of DoTokenChain@54
    DoTokenChain:1@0: ["s.Mode:" s.STAT_Mode "s.Kind:" s.STAT_Kind "t.ErrorList:" t.STAT_ErrorList "e.Collected:" (e.STAT_Collected) "e.Tokens:" (e.STAT_Tokens) e.dyn]
    DoTokenChain@9: [s.0 s.1 t.2 (e.3 (Symbol Char s.4)) e.5]
    DoTokenChain@54: [Extended s.0 t.1 (e.2 (Symbol Char s.3) (Symbol Name t.4 e.5)) e.6]

Sun Aug 01 00:37:26 2021: History of DoTokenChain:1$11=1@26
    DoTokenChain:1@0: ["s.Mode:" s.STAT_Mode "s.Kind:" s.STAT_Kind "t.ErrorList:" t.STAT_ErrorList "e.Collected:" (e.STAT_Collected) "e.Tokens:" (e.STAT_Tokens) e.dyn]
    DoTokenChain@9: [s.0 s.1 t.2 (e.3 (Symbol Char s.4)) e.5]
    DoTokenChain:1$11=1@26: ["s.Mode:" Classic "s.Kind:" s.0 "e.Collected:" (e.1 (Symbol Char s.2)) e.3 () e.4]

Специализация начинается во вспомогательной функции-блоке DoTokenChain:1. Данный блок самостоятельно вызываться не должен, он должен почти полностью (до предложения с условием , s.Kind : Result) прогнаться в точку вызова. Если бы блок прогнался, то рекурсивные вызовы DoTokenChain не стали бы специализироваться, т.к. сработало бы условие остановки.

Вывод

  • [x] ~~Нужно реализовывать #228.~~ Не актуально, собралось и без этого.

Mazdaywik avatar Jul 31 '21 22:07 Mazdaywik

Удалось самоприменить компилятор в режиме

set RLMAKE_FLAGS=-X-OiADPRS

Сводка по операциям:

Total program time: 829.21900 seconds (100.0 %).
(Total refal time): 575.79400 seconds (69.4 %).
Linear pattern time: 234.95600 seconds (28.3 %).
Runtime time overhead: 207.42800 seconds (25.0 %).
Linear result time: 165.24800 seconds (19.9 %).
Open e-loop time (clear): 91.90000 seconds (11.1 %).
t- and e-var copy time: 68.27100 seconds (8.2 %).
Native time: 45.68600 seconds (5.5 %).
Repeated t-var match time (inside e-loops): 9.11900 seconds (1.1 %).
Repeated e-var match time (inside e-loops): 4.99000 seconds (0.6 %).
Repeated e-var match time (outside e-loops): 1.23300 seconds (0.1 %).
Context copy time: 0.31100 seconds (0.0 %).
Repeated t-var match time (outside e-loops): 0.07700 seconds (0.0 %).
Step count 625451933
Identifiers allocated: 2475
Memory used 23749000 nodes, 23749000 * 16 = 379984000 bytes

Число шагов 625 451 933 с существенным запасом меньше лимита 2 000 000 000. Общее время тоже вполне приемлемо.

Профиль по счётчику:

Total time: 829.12500 s
Total semisteps (function calls and closure unwraps): 626381506
Mean semistep time: 1.323674 us

__Step-Drop (0000) -> 29745742 (4.75 %, += 4.75 %)                                 rel step time 0.35
Map@3 (2795) -> 21410913 (3.42 %, += 8.17 %)                                       rel step time 0.73
FilterPatternPos (2795) -> 21166839 (3.38 %, += 11.55 %)                            rel step time 1.09
Map@4 (2795) -> 19903338 (3.18 %, += 14.72 %)                                       rel step time 0.70
FilterResultPos (2795) -> 19659264 (3.14 %, += 17.86 %)                             rel step time 1.19
ApplyContraction-toExpr (0946) -> 15185678 (2.42 %, += 20.29 %)                     rel step time 1.98
Compare-Digits (3087) -> 15089979 (2.41 %, += 22.70 %)                              rel step time 0.29
Compare (0000) -> 15004120 (2.40 %, += 25.09 %)                                     rel step time 0.84
Type (0000) -> 14712340 (2.35 %, += 27.44 %)                                        rel step time 0.34
InlineTerm (6778) -> 13465607 (2.15 %, += 29.59 %)                                  rel step time 0.69
DoInlineExpr (6778) -> 13465607 (2.15 %, += 31.74 %)                                rel step time 0.86
DoIsIdent (6778) -> 13458436 (2.15 %, += 33.89 %)                                   rel step time 0.98
Map@1 (0795) -> 12377835 (1.98 %, += 35.86 %)                                       rel step time 0.86
DoIsIdent$3?1 (6778) -> 10951750 (1.75 %, += 37.61 %)                               rel step time 0.70
AppendTerm (6778) -> 10627286 (1.70 %, += 39.31 %)                                  rel step time 0.71
Ord (0000) -> 9995802 (1.60 %, += 40.90 %)                                         rel step time 0.33
CharRep (6778) -> 9835537 (1.57 %, += 42.48 %)                                     rel step time 1.01
CharRep$7?2 (6778) -> 9833499 (1.57 %, += 44.04 %)                                 rel step time 0.63
CharRep$7?1 (6778) -> 9833499 (1.57 %, += 45.61 %)                                 rel step time 0.75
ExtractVariables-Expr (0000) -> 9650856 (1.54 %, += 47.16 %)                       rel step time 0.85
Symbol (6778) -> 9447372 (1.51 %, += 48.66 %)                                      rel step time 0.68
ZipItems (2795) -> 8685200 (1.39 %, += 50.05 %)                                    rel step time 1.10

_profile_count.txt

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

Профиль по времени:

Total time: 829.12500 s
Total semisteps (function calls and closure unwraps): 626381506
Mean semistep time: 1.323674 us

ApplyContraction-toExpr (0946) -> 39770.0 ms (4.80 %, += 4.80 %)                     rel step time 1.98
Solve-Clashes (0946) -> 35484.0 ms (4.28 %, += 9.08 %)                               rel step time 9.01
FilterResultPos (2795) -> 30953.0 ms (3.73 %, += 12.81 %)                             rel step time 1.19
FilterPatternPos (2795) -> 30672.0 ms (3.70 %, += 16.51 %)                            rel step time 1.09
Map@3 (2795) -> 20630.0 ms (2.49 %, += 19.00 %)                                       rel step time 0.73
Map@4 (2795) -> 18416.0 ms (2.22 %, += 21.22 %)                                       rel step time 0.70
DoIsIdent (6778) -> 17538.0 ms (2.12 %, += 23.33 %)                                   rel step time 0.98
Compare (0000) -> 16709.0 ms (2.02 %, += 25.35 %)                                     rel step time 0.84
DoInlineExpr (6778) -> 15314.0 ms (1.85 %, += 27.20 %)                                rel step time 0.86
Map@1 (0795) -> 14118.0 ms (1.70 %, += 28.90 %)                                       rel step time 0.86
__Step-Drop (0000) -> 13677.0 ms (1.65 %, += 30.55 %)                                 rel step time 0.35
CharRep (6778) -> 13131.0 ms (1.58 %, += 32.13 %)                                     rel step time 1.01
ZipItems (2795) -> 12697.0 ms (1.53 %, += 33.66 %)                                    rel step time 1.10
InlineTerm (6778) -> 12309.0 ms (1.48 %, += 35.15 %)                                  rel step time 0.69
OverlapItem (2795) -> 12021.0 ms (1.45 %, += 36.60 %)                                 rel step time 1.14
DoMapAccum@2 (2795) -> 11333.0 ms (1.37 %, += 37.96 %)                                rel step time 1.71
ExtractVariables-Expr (0000) -> 10883.0 ms (1.31 %, += 39.28 %)                       rel step time 0.85
DoIsIdent$3?1 (6778) -> 10205.0 ms (1.23 %, += 40.51 %)                               rel step time 0.70
AppendTerm (6778) -> 9990.0 ms (1.20 %, += 41.71 %)                                  rel step time 0.71
CharRep$7?1 (6778) -> 9791.0 ms (1.18 %, += 42.89 %)                                 rel step time 0.75
Add (0000) -> 8869.0 ms (1.07 %, += 43.96 %)                                         rel step time 0.90
Symbol (6778) -> 8549.0 ms (1.03 %, += 44.99 %)                                      rel step time 0.68
DisplayName (0000) -> 8530.0 ms (1.03 %, += 46.02 %)                                 rel step time 1.69
CharRep$7?2 (6778) -> 8170.0 ms (0.99 %, += 47.01 %)                                 rel step time 0.63
SimplifyCoordinates-Expr (0946) -> 7842.0 ms (0.95 %, += 47.95 %)                    rel step time 1.15
FindHeavyTile\1:1 (2795) -> 7678.0 ms (0.93 %, += 48.88 %)                           rel step time 1.18
OptTree-Spec (0000) -> 7493.0 ms (0.90 %, += 49.78 %)                                rel step time 14403.97
DoOverlapOffsets (2795) -> 7135.0 ms (0.86 %, += 50.64 %)                            rel step time 7.51

_profile_time.txt

Заметную долю имеет применение сужений и обобщённое сопоставление с образцом.

Mazdaywik avatar Aug 01 '21 16:08 Mazdaywik

Комментарий не сворачивать, на него есть ссылка.

Реализованы последовательные сужения. Профиль по числу шагов:

Total time: 814.20300 s
Total semisteps (function calls and closure unwraps): 618754069
Mean semistep time: 1.315875 us

__Step-Drop (0000) -> 29905206 (4.83 %, += 4.83 %)                                 rel step time 0.35
Map@3 (2795) -> 21523951 (3.48 %, += 8.31 %)                                       rel step time 0.72
FilterPatternPos (2795) -> 21278445 (3.44 %, += 11.75 %)                            rel step time 1.14
Map@4 (2795) -> 20019814 (3.24 %, += 14.99 %)                                       rel step time 0.66
FilterResultPos (2795) -> 19774308 (3.20 %, += 18.18 %)                             rel step time 1.27
Compare-Digits (3087) -> 15158343 (2.45 %, += 20.63 %)                              rel step time 0.35
Compare (0000) -> 15071937 (2.44 %, += 23.07 %)                                     rel step time 0.83
Type (0000) -> 14728026 (2.38 %, += 25.45 %)                                        rel step time 0.36
InlineTerm (6778) -> 13487837 (2.18 %, += 27.63 %)                                  rel step time 0.74
DoInlineExpr (6778) -> 13487837 (2.18 %, += 29.81 %)                                rel step time 0.84
DoIsIdent (6778) -> 13466188 (2.18 %, += 31.98 %)                                   rel step time 1.00
Map@1 (0795) -> 12277929 (1.98 %, += 33.97 %)                                       rel step time 0.80
DoIsIdent$3?1 (6778) -> 10958379 (1.77 %, += 35.74 %)                               rel step time 0.70
AppendTerm (6778) -> 10642225 (1.72 %, += 37.46 %)                                  rel step time 0.75
Ord (0000) -> 10042893 (1.62 %, += 39.08 %)                                         rel step time 0.40
CharRep (6778) -> 9881586 (1.60 %, += 40.68 %)                                     rel step time 1.00
CharRep$7?2 (6778) -> 9879544 (1.60 %, += 42.28 %)                                 rel step time 0.69
CharRep$7?1 (6778) -> 9879544 (1.60 %, += 43.87 %)                                 rel step time 0.87
Symbol (6778) -> 9458920 (1.53 %, += 45.40 %)                                      rel step time 0.60
ZipItems (2795) -> 8727603 (1.41 %, += 46.81 %)                                    rel step time 1.10
DoMapAccum@2 (4824) -> 8588637 (1.39 %, += 48.20 %)                                rel step time 0.76
DoMapAccum$1=1@1 (4824) -> 8588637 (1.39 %, += 49.59 %)                            rel step time 0.85
ApplyContractions-Term (4824) -> 8588637 (1.39 %, += 50.98 %)                      rel step time 1.93

_profile_count.txt

Профиль по времени:

Total time: 814.20300 s
Total semisteps (function calls and closure unwraps): 618754069
Mean semistep time: 1.315875 us

Solve-Clashes (8459) -> 38510.0 ms (4.73 %, += 4.73 %)                               rel step time 9.51
FilterResultPos (2795) -> 33064.0 ms (4.06 %, += 8.79 %)                             rel step time 1.27
FilterPatternPos (2795) -> 32008.0 ms (3.93 %, += 12.72 %)                            rel step time 1.14
ApplyContractions-Term (4824) -> 21866.0 ms (2.69 %, += 15.41 %)                      rel step time 1.93
Map@3 (2795) -> 20426.0 ms (2.51 %, += 17.92 %)                                       rel step time 0.72
DoIsIdent (6778) -> 17800.0 ms (2.19 %, += 20.10 %)                                   rel step time 1.00
Map@4 (2795) -> 17336.0 ms (2.13 %, += 22.23 %)                                       rel step time 0.66
Compare (0000) -> 16403.0 ms (2.01 %, += 24.25 %)                                     rel step time 0.83
DoInlineExpr (6778) -> 14981.0 ms (1.84 %, += 26.09 %)                                rel step time 0.84
__Step-Drop (0000) -> 13956.0 ms (1.71 %, += 27.80 %)                                 rel step time 0.35
InlineTerm (6778) -> 13133.0 ms (1.61 %, += 29.41 %)                                  rel step time 0.74
CharRep (6778) -> 12983.0 ms (1.59 %, += 31.01 %)                                     rel step time 1.00
Map@1 (0795) -> 12968.0 ms (1.59 %, += 32.60 %)                                       rel step time 0.80
ZipItems (2795) -> 12587.0 ms (1.55 %, += 34.15 %)                                    rel step time 1.10
OverlapItem (2795) -> 11437.0 ms (1.40 %, += 35.55 %)                                 rel step time 1.08
CharRep$7?1 (6778) -> 11260.0 ms (1.38 %, += 36.93 %)                                 rel step time 0.87
AppendTerm (6778) -> 10438.0 ms (1.28 %, += 38.22 %)                                  rel step time 0.75
DoIsIdent$3?1 (6778) -> 10075.0 ms (1.24 %, += 39.45 %)                               rel step time 0.70
DoMapAccum@2 (2795) -> 9959.0 ms (1.22 %, += 40.68 %)                                rel step time 1.51
DoMapAccum$1=1@1 (4824) -> 9630.0 ms (1.18 %, += 41.86 %)                            rel step time 0.85
ApplyContraction-toExpr (8459) -> 9057.0 ms (1.11 %, += 42.97 %)                     rel step time 2.12
CharRep$7?2 (6778) -> 9018.0 ms (1.11 %, += 44.08 %)                                 rel step time 0.69
DoMapAccum@2 (4824) -> 8637.0 ms (1.06 %, += 45.14 %)                                rel step time 0.76
Map@20 (8459) -> 8615.0 ms (1.06 %, += 46.20 %)                                      rel step time 3.57
DisplayName (0000) -> 8281.0 ms (1.02 %, += 47.22 %)                                 rel step time 1.65
FindHeavyTile\1:1 (2795) -> 8191.0 ms (1.01 %, += 48.22 %)                           rel step time 1.26
Add (0000) -> 7815.0 ms (0.96 %, += 49.18 %)                                         rel step time 0.79
Symbol (6778) -> 7428.0 ms (0.91 %, += 50.09 %)                                      rel step time 0.60

_profile_time.txt

В обоих профилях очевидна отладочная печать, бесполезная при компиляции в RASL:

        14. #6778 - Log-AST.ref
  • [x] Следует данную отладочную печать откладывать — вместо (CmdComment s.CHAR*) формировать (CmdComment s.Func), где <s.Func> == s.CHAR*. При необходимости печати комментариев (генерация нативного кода, вывод в лог) функция будет вызываться. Недостаток — при включённом логировании и компиляции в нативный код комментарии будут вычисляться дважды. Но это не страшно, т.к. высокое быстродействие при включённом логе никто не гарантирует.

Mazdaywik avatar Aug 01 '21 21:08 Mazdaywik

Удалось самоприменить компилятор в режиме

set RLMAKE_FLAGS=-X-OiADGPRS

А это почти все доступные оптимизации, все, кроме -Od.

Сводка по операциям:

Total program time: 1550.29600 seconds (100.0 %).
(Total refal time): 1289.80900 seconds (83.2 %).
Open e-loop time (clear): 546.69400 seconds (35.3 %).
Linear pattern time: 253.33500 seconds (16.3 %).
Repeated t-var match time (inside e-loops): 202.35200 seconds (13.1 %).
Runtime time overhead: 199.61600 seconds (12.9 %).
Linear result time: 171.70800 seconds (11.1 %).
t- and e-var copy time: 62.93600 seconds (4.1 %).
Native time: 60.73100 seconds (3.9 %).
Repeated e-var match time (inside e-loops): 51.86900 seconds (3.3 %).
Repeated e-var match time (outside e-loops): 0.87000 seconds (0.1 %).
Context copy time: 0.14000 seconds (0.0 %).
Repeated t-var match time (outside e-loops): 0.04500 seconds (0.0 %).
Step count 864041659
Identifiers allocated: 2465
Memory used 53652000 nodes, 53652000 * 16 = 858432000 bytes

Время 1550 секунд ≈ 26 минут, что ожидаемо для такого режима. Число шагов тоже ожидаемо, потребление памяти немного менее гигабайта.

Профиль по числу шагов:

Total time: 1550.21800 s
Total semisteps (function calls and closure unwraps): 865027918
Mean semistep time: 1.792102 us

__Step-Drop (0000) -> 54362446 (6.28 %, += 6.28 %)                                 rel step time 0.19
Map@3 (8199) -> 34801839 (4.02 %, += 10.31 %)                                       rel step time 0.57
UnionChildren (3051) -> 32396077 (3.75 %, += 14.05 %)                               rel step time 7.13
Map@4 (8199) -> 32258816 (3.73 %, += 17.78 %)                                       rel step time 0.58
FilterResultPos*2 (8199) -> 30566718 (3.53 %, += 21.32 %)                           rel step time 0.49
FilterPatternPos*2 (8199) -> 30288843 (3.50 %, += 24.82 %)                          rel step time 0.48
Compare-Digits (3087) -> 29670134 (3.43 %, += 28.25 %)                              rel step time 0.18
Compare (0000) -> 29533652 (3.41 %, += 31.66 %)                                     rel step time 0.46
Type (0000) -> 23767225 (2.75 %, += 34.41 %)                                        rel step time 0.21
DoInlineExpr (4769) -> 21572998 (2.49 %, += 36.90 %)                                rel step time 0.70
Ord (0000) -> 21122285 (2.44 %, += 39.34 %)                                         rel step time 0.21
CharRep*6$7?2 (4769) -> 20898530 (2.42 %, += 41.76 %)                               rel step time 0.36
CharRep*6$7?1 (4769) -> 20898530 (2.42 %, += 44.18 %)                               rel step time 0.49
CharRep*6 (4769) -> 20898530 (2.42 %, += 46.59 %)                                   rel step time 0.44
DoIsIdent@2 (4769) -> 16046765 (1.86 %, += 48.45 %)                                 rel step time 0.53
DoCompound (4769) -> 14871585 (1.72 %, += 50.17 %)                                  rel step time 0.49

_profile_count.txt

Профиль по времени:

Total time: 1550.21800 s
Total semisteps (function calls and closure unwraps): 865027918
Mean semistep time: 1.792102 us

UnionChildren (3051) -> 413914.0 ms (26.70 %, += 26.70 %)                               rel step time 7.13
ApplyInlines-Children (3051) -> 127650.0 ms (8.23 %, += 34.93 %)                       rel step time 461.20
DoBasicVertexes (3051) -> 62160.0 ms (4.01 %, += 38.94 %)                             rel step time 42.74
Map@3 (8199) -> 35361.0 ms (2.28 %, += 41.23 %)                                       rel step time 0.57
Map@4 (8199) -> 33352.0 ms (2.15 %, += 43.38 %)                                       rel step time 0.58
SpecUnit (0601) -> 29154.0 ms (1.88 %, += 45.26 %)                                    rel step time 42.67
FilterResultPos*2 (8199) -> 27081.0 ms (1.75 %, += 47.00 %)                           rel step time 0.49
DoInlineExpr (4769) -> 26900.0 ms (1.74 %, += 48.74 %)                                rel step time 0.70
UpdateTable (2500) -> 26259.0 ms (1.69 %, += 50.43 %)                                 rel step time 148.39

_profile_time.txt

Из счётчика шагов видно то же, что и в предыдущем комментарии — нужно откладывать построение текста в CmdComment.

Профиль по времени показывает более интересную картину — первые три строчки (≈39 %) занимает устаревшая функциональность авторазметки.

Mazdaywik avatar Aug 02 '21 04:08 Mazdaywik

А вот в режиме

set SCRIPT_FLAGS=--scratch
set RLMAKE_FLAGS=-X-OdiADGPRS

не хватило памяти:

*Generating code...

NO MEMORY


Total program time: 1674.42200 seconds (100.0 %).
(Total refal time): 1346.15400 seconds (80.4 %).
Open e-loop time (clear): 531.36600 seconds (31.7 %).
Linear pattern time: 283.66800 seconds (16.9 %).
Runtime time overhead: 266.16700 seconds (15.9 %).
Repeated t-var match time (inside e-loops): 208.92000 seconds (12.5 %).
Linear result time: 206.68200 seconds (12.3 %).
t- and e-var copy time: 64.99300 seconds (3.9 %).
Native time: 61.58300 seconds (3.7 %).
Repeated e-var match time (inside e-loops): 49.40100 seconds (3.0 %).
Repeated e-var match time (outside e-loops): 1.01500 seconds (0.1 %).
Context copy time: 0.51800 seconds (0.0 %).
Repeated t-var match time (outside e-loops): 0.10900 seconds (0.0 %).
Step count 897439681
Identifiers allocated: 1740
Memory used 69999000 nodes, 69999000 * 16 = 1119984000 bytes

Mazdaywik avatar Aug 02 '21 05:08 Mazdaywik

При самоприменении в режиме

set RLMAKE_FLAGS=-X-OdiADGPRS
set SCRIPT_FLAGS=--scratch --debug

компиляция вылетает с уже известной ошибкой:

Turbo Incremental Link 5.00 Copyright (c) 1997, 2000 Borland
Fatal: Error detected (LME2053)
Fatal: Error detected (LME1642)
Fatal: Error detected (LME1577)
Fatal: Error detected (LME1657)
Fatal: Access violation.  Link terminated.

Ошибка была обнаружена 28 ноября прошлого года: https://github.com/bmstu-iu9/refal-5-lambda/issues/319#issuecomment-735123922.

Ранее (см. ссылку выше) объём не слинковавшегося файла составлял 955 990 строк, его приходилось разбивать на части, чтобы слинковать — слишком большие объектники линковщик BCC 5.5.1 не принимал.

Теперь объём _rlc-core.exe.cpp стал ещё больше. Опять таки, если его разбить на два, компоновка выполняется. Длины строк исходного файла и после разбиения:

  1671407 _rlc-core.exe.cpp
  1094387 _rlc-core1.exe.cpp
   588373 _rlc-core2.exe.cpp

Суммарный объём не совпадает, т.к. в обоих частях общий заголовок — enum’ы для идентификаторов и функций.

Текущий объём _rlc-core.exe.cpp много больше, чем в прошлый раз, так что нечего бороться за его объём и данный режим компиляции по умолчанию.

Mazdaywik avatar Aug 06 '21 12:08 Mazdaywik

Реализовал отложенное формирование текстового представления выражений. Самоприменил в режиме:

set RLMAKE_FLAGS=-X-OiADPRS

Общая сводка:

Total program time: 520.20300 seconds (100.0 %).
(Total refal time): 382.12300 seconds (73.5 %).
Linear pattern time: 148.27300 seconds (28.5 %).
Runtime time overhead: 116.14200 seconds (22.3 %).
Linear result time: 93.83700 seconds (18.0 %).
t- and e-var copy time: 64.40400 seconds (12.4 %).
Open e-loop time (clear): 63.49900 seconds (12.2 %).
Native time: 21.63900 seconds (4.2 %).
Repeated t-var match time (inside e-loops): 7.21600 seconds (1.4 %).
Repeated e-var match time (inside e-loops): 3.97400 seconds (0.8 %).
Repeated e-var match time (outside e-loops): 0.85600 seconds (0.2 %).
Context copy time: 0.29900 seconds (0.1 %).
Repeated t-var match time (outside e-loops): 0.06400 seconds (0.0 %).
Step count 422863403
Identifiers allocated: 2475
Memory used 23749000 nodes, 23749000 * 16 = 379984000 bytes

Профиль числа шагов

Total time: 520.14000 s
Total semisteps (function calls and closure unwraps): 423808075
Mean semistep time: 1.227301 us

Map@3 (2795) -> 21504906 (5.07 %, += 5.07 %)                                       rel step time 0.61
FilterPatternPos (2795) -> 21259604 (5.02 %, += 10.09 %)                            rel step time 0.98
Map@4 (2795) -> 20002418 (4.72 %, += 14.81 %)                                       rel step time 0.58
FilterResultPos (2795) -> 19757116 (4.66 %, += 19.47 %)                             rel step time 0.96
__Step-Drop (0000) -> 18744356 (4.42 %, += 23.89 %)                                 rel step time 0.34
Map@1 (0795) -> 12265008 (2.89 %, += 26.79 %)                                       rel step time 0.67
ZipItems (2795) -> 8719721 (2.06 %, += 28.85 %)                                    rel step time 0.89
DoMapAccum@2 (7093) -> 8707540 (2.05 %, += 30.90 %)                                rel step time 0.72
DoMapAccum$1=1@1 (7093) -> 8707540 (2.05 %, += 32.96 %)                            rel step time 0.72
ApplyContractions-Term (7093) -> 8707540 (2.05 %, += 35.01 %)                      rel step time 1.62
OverlapItem (2795) -> 8018652 (1.89 %, += 36.90 %)                                 rel step time 0.98
Add (0000) -> 7484851 (1.77 %, += 38.67 %)                                         rel step time 0.76
Add-Digits (3087) -> 7400515 (1.75 %, += 40.41 %)                                  rel step time 0.33
ExtractVariables-Expr (0000) -> 6530437 (1.54 %, += 41.96 %)                       rel step time 0.68
FoldTile-EEnd (2795) -> 5765124 (1.36 %, += 43.32 %)                               rel step time 0.74
Compare-Digits (3087) -> 5306355 (1.25 %, += 44.57 %)                              rel step time 0.32
Compare (0000) -> 5220039 (1.23 %, += 45.80 %)                                     rel step time 0.78
DoMapAccum@2 (2795) -> 5005632 (1.18 %, += 46.98 %)                                rel step time 1.46
GlueTiles (2795) -> 4963077 (1.17 %, += 48.15 %)                                   rel step time 0.64
FindHeavyTile\1:1 (2795) -> 4910273 (1.16 %, += 49.31 %)                           rel step time 1.02
DoMapAccum$1=1@1 (2795) -> 4910273 (1.16 %, += 50.47 %)                            rel step time 0.66

_profile_count.txt

Профиль по времени:

Total time: 520.14000 s
Total semisteps (function calls and closure unwraps): 423808075
Mean semistep time: 1.227301 us

Solve-Clashes (8459) -> 29641.0 ms (5.70 %, += 5.70 %)                               rel step time 7.85
FilterPatternPos (2795) -> 25545.0 ms (4.91 %, += 10.61 %)                            rel step time 0.98
FilterResultPos (2795) -> 23389.0 ms (4.50 %, += 15.11 %)                             rel step time 0.96
ApplyContractions-Term (7093) -> 17335.0 ms (3.33 %, += 18.44 %)                      rel step time 1.62
Map@3 (2795) -> 16163.0 ms (3.11 %, += 21.55 %)                                       rel step time 0.61
Map@4 (2795) -> 14168.0 ms (2.72 %, += 24.27 %)                                       rel step time 0.58
Map@1 (0795) -> 10118.0 ms (1.95 %, += 26.22 %)                                       rel step time 0.67
OverlapItem (2795) -> 9626.0 ms (1.85 %, += 28.07 %)                                 rel step time 0.98
ZipItems (2795) -> 9489.0 ms (1.82 %, += 29.89 %)                                    rel step time 0.89
DoMapAccum@2 (2795) -> 8949.0 ms (1.72 %, += 31.61 %)                                rel step time 1.46
__Step-Drop (0000) -> 7711.0 ms (1.48 %, += 33.09 %)                                 rel step time 0.34
DoMapAccum$1=1@1 (7093) -> 7707.0 ms (1.48 %, += 34.58 %)                            rel step time 0.72
DoMapAccum@2 (7093) -> 7694.0 ms (1.48 %, += 36.05 %)                                rel step time 0.72
ApplyContraction-toExpr (8459) -> 7443.0 ms (1.43 %, += 37.49 %)                     rel step time 1.87
Add (0000) -> 6994.0 ms (1.34 %, += 38.83 %)                                         rel step time 0.76
Solve-Clashes$26=3 (8459) -> 6519.0 ms (1.25 %, += 40.08 %)                          rel step time 28.47
Map@20 (8459) -> 6443.0 ms (1.24 %, += 41.32 %)                                      rel step time 2.86
OptTree-Spec (0000) -> 6214.0 ms (1.19 %, += 42.52 %)                                rel step time 12818.08
FindHeavyTile\1:1 (2795) -> 6124.0 ms (1.18 %, += 43.69 %)                           rel step time 1.02
DoOverlapOffsets (2795) -> 5953.0 ms (1.14 %, += 44.84 %)                            rel step time 6.74
ExtractVariables-Expr (0000) -> 5421.0 ms (1.04 %, += 45.88 %)                       rel step time 0.68
ClearCoordinates (8459) -> 5267.0 ms (1.01 %, += 46.89 %)                            rel step time 0.90
FoldTile-EEnd (2795) -> 5241.0 ms (1.01 %, += 47.90 %)                               rel step time 0.74
Compare (0000) -> 5010.0 ms (0.96 %, += 48.86 %)                                     rel step time 0.78
SimplifyCoordinates (8459) -> 4190.0 ms (0.81 %, += 49.67 %)                         rel step time 0.92
Unique (0000) -> 4162.0 ms (0.80 %, += 50.47 %)                                      rel step time 2.82

_profile_time.txt

Видно, что в профиле до 50 % отсутствуют функции формирования выражений (InlineExpr, InlineTerm и др.). Различие по времени (в https://github.com/bmstu-iu9/refal-5-lambda/issues/359#issuecomment-890589201 было 814 секунд, здесь 520), возможно, объясняется некорректным замером в прошлый раз (компьютер был занят).

Любопытным оказалось и то, что не только CmdComment съедал время, но и вывод сигнатур в лог.

Mazdaywik avatar Aug 07 '21 08:08 Mazdaywik

@TonitaN, этот комментарий тебе может быть интересен.

Алгоритм обобщённого сопоставления для проверки экранирования предложений

Историческая картина

Когда @nexterot реализовывал распознавание экранирования предложений (#256), возникла потребность в алгоритме сопоставления, умеющем открытые переменные. Имеющийся алгоритм сопоставления, используемый для прогонки, по этой причине не подходил.

@TonitaN нам (мне и @nexterot’у) сказала (на сколько я помню), что если в компиляторе есть алгоритм, который умеет сопоставлять произвольное объектное выражение с произвольным образцом, то можно использовать его — нужно трактовать переменные как особый сорт символов. Такого алгоритма не было, @nexterot решил его реализовать.

@nexterot скопировал GenericMatch.ref в ObjectMatch.ref, добавил поддержку открытых переменных ровно в том объёме, которого достаточно для распознавания экранирования. Всё заработало.

Актуальная ситуация

Сейчас в компиляторе появился алгоритм, который может сопоставлять произвольное объектное выражение с произвольным образцом — это новый алгоритм обобщённого сопоставления (#322). Чтобы избежать дублирования логики, я решил заиспользовать его.

Но если трактовать переменные как символы буквально — вместо (Var …) использовать, скажем, (Symbol Var …), то результат сопоставления будет неадекватен. Любые символы могут сопоставляться с s-переменными, поэтому s-переменной может оказаться присвоена и t-, и даже e-переменная.

Поэтому в выражение был добавлен новый сорт элементов (хочется написать, «термов», но под термами я привык понимать рефал-термы) — экранированные переменные, (ScrVar …). Экранированные s-переменные могут сопоставляться с s-переменными, экранированные t-переменные — с t-переменными, всё, как и ожидается.

Однако, есть отличия:

  • Экранированные переменные нельзя сужать. Там, где для обычной переменной формируется сужение, здесь ветка решения усекается («решений нет»).
  • При сопоставлении с открытыми переменными, между экранированными переменными (любого типа) добавляются точки разделения точно также, как и между термами. Смысл данного поведения в том, что для подготовленного образца содержательная проверка на вложение сводится к синтаксической — наличию подстановки. Поэтому нам не нужно рассматривать расщепления e-переменных.

Интересно заметить, что использование алгоритма обобщённого сопоставления позволило глубже анализировать предложения. В начале был подготовлен набор тестов (не закоммичен) — сгенерировано 120 случайных программ, для них старым алгоритмом были получены эталонные предупреждения. Ожидалось, что новый алгоритм при правильной реализации воспроизведёт те же предупреждения. Однако, новый алгоритм выявил больше предупреждений, чем старый (но ни одно старое не потерял). Предложения, на которых были выявлены экранирования, перенесены в автотесты, которые можно наблюдать в коммите c734d62dc1c0051a9247cb963be6a8be75d7c8c2.

Связь с неразменными переменными (#231)

Ряд расширений прогонки (#230, #231, #283) требуют рассмотрения т.н. «неразменных» переменных — переменных, которые запрещено сужать. Если при прогонке требуется сужение такой переменной, то попытка прогонки данного вызова отклоняется.

На данный момент «целые» переменные реализованы как список e.WholeVars (https://github.com/bmstu-iu9/refal-5-lambda/commit/1ef5b6c47cd997102af9e5361e6b9ea8d9a29cf3, https://github.com/bmstu-iu9/refal-5-lambda/commit/e1a0b3199cd490adb77d53e7524241243d9c4176). Если при прогонке очередного предложения появляются сужения на e.WholeVars, то данная прогонка отклоняется.

Поведение экранированных переменных (ScrVar …) похоже на поведение «целых» переменных.

Первое отличие состоит в том, что при сужениях экранированных переменных ветвь усекается с отсутствием решения, а для целых переменных ветвь должна усекаться с выдачей Undefined. Казалось бы, можно убить двух зайцев, сделать (ScrVar …) неразменными переменными (назвав их, например, (WhVar …)), и выдавать Undefined. С точки зрения проверки на вложение это было бы допустимо, т.к. в обоих случаях не будет чистого решения. Но есть второе отличие.

Второе отличие в сопоставлении с открытыми переменными. Если выражение с экранированными переменными мы можем сопоставлять с образцом с открытыми переменными (трактуя их как термы), то выражение с целыми переменными сопоставлять с открытыми переменными нельзя — сразу должен быть Undefined. А для обнаружения экранирования нужно именно усечение веток — для поиска подходящей подстановки.

Так что можно реализовать работу с целыми переменными на уровне алгоритма обобщённого сопоставления по некоторой аналогии с экранируемыми переменными. Но объединять их нельзя.

Про кортежи и коммиты 5522663c1ceb83b12d5260fa36b1a3b1dfc84ac6, 4283a70d43be0f6713fa37dd22f4b05114506fb8

Ранее мы втроём (@nexterot, @TonitaN и я) обсуждали, что проверка вложения для языков образцов определена только для плоских образцов, т.е. без скобок. И чтобы преодолеть это ограничение, я предложил выбрать только различающиеся части двух образцов, и их попарно сравнить. Для выбора различающихся частей я предложил вычислить обобщение обоих образцов, сопоставить каждый из них с обобщением и спарить соответствующие сопоставления с переменными. Собственно, это и было сделано.

Но, если при сопоставлении E : P образец и выражение являются уточнениями одного и того же жёсткого выражения, то при сопоставлении в первую очередь разберётся их общая структура. Причём разберётся она транзитными шагами, т.е. без сужений. А значит, принудительно искать обобщение и сопоставлять их фрагменты не нужно, оно и так сработает само. Поэтому можно тупо сопоставлять один образец с другим, получая тот же самый результат (предупреждения на наборе тестов сохранились).

Вопрос производительности

Попробовал я самоприменить компилятор в режиме

set RLMAKE_FLAGS=-X-OiDPRS -X-Wscreening

Компилятор вылетел по лимиту шагов:

*Compiling Checker.ref:
*Compiling GenericMatch.ref:

STEP LIMIT REACHED (2000000000)


Total program time: 2962.14000 seconds (100.0 %).
(Total refal time): 2144.30600 seconds (72.4 %).
Runtime time overhead: 815.95000 seconds (27.5 %).
Open e-loop time (clear): 756.40500 seconds (25.5 %).
Linear pattern time: 575.11900 seconds (19.4 %).
Linear result time: 497.31500 seconds (16.8 %).
t- and e-var copy time: 305.68700 seconds (10.3 %).
Repeated t-var match time (inside e-loops): 7.28800 seconds (0.2 %).
Repeated e-var match time (outside e-loops): 2.08600 seconds (0.1 %).
Native time: 1.88400 seconds (0.1 %).
Repeated e-var match time (inside e-loops): 0.39000 seconds (0.0 %).
Repeated t-var match time (outside e-loops): 0.01600 seconds (0.0 %).

Вылет на GenericMatch.ref ожидаемый. Поиск экранируемых предложений имеет квадратичную сложность от числа предложений в функции, а в GenericMatch есть функции с десятками предложений и довольно сложными образцами. Но интересен результат профилирования (оба показаны до 50 %):

Счётчик шагов:

Total time: 2961.90700 s
Total semisteps (function calls and closure unwraps): 2000059607
Mean semistep time: 1.480909 us

ClearCoordinates (2023) -> 287903887 (14.39 %, += 14.39 %)                            rel step time 0.58
Map@8 (2023) -> 61682923 (3.08 %, += 17.48 %)                                       rel step time 0.43
IsTerm (2023) -> 41331241 (2.07 %, += 19.55 %)                                      rel step time 0.70
SeparateTermLeft (2023) -> 41156418 (2.06 %, += 21.60 %)                            rel step time 0.75
HasTopLevelCoordinateLabels (2023) -> 41106970 (2.06 %, += 23.66 %)                 rel step time 0.58
IsTautology=2 (2023) -> 41104991 (2.06 %, += 25.71 %)                               rel step time 0.45
IsTautology=1 (2023) -> 41104991 (2.06 %, += 27.77 %)                               rel step time 0.54
IsTautology (2023) -> 41104991 (2.06 %, += 29.82 %)                                 rel step time 0.61
Eq (2023) -> 41104991 (2.06 %, += 31.88 %)                                          rel step time 0.47
RemoveTautologies\1$1?1 (2023) -> 41104808 (2.06 %, += 33.93 %)                     rel step time 0.38
RemoveTautologies\1 (2023) -> 41104808 (2.06 %, += 35.99 %)                         rel step time 0.97
gen_e__ (2023) -> 20796671 (1.04 %, += 37.03 %)                                     rel step time 0.40
IsSVarSubset (2023) -> 20588782 (1.03 %, += 38.06 %)                                rel step time 0.78
RemoveTautologies (2023) -> 20578115 (1.03 %, += 39.09 %)                           rel step time 0.38
Solve-SymmClashes=1 (2023) -> 20565239 (1.03 %, += 40.12 %)                         rel step time 0.62
Solve-SymmClashes-Aux (2023) -> 20565239 (1.03 %, += 41.14 %)                       rel step time 1.13
Solve-SymmClashes (2023) -> 20565239 (1.03 %, += 42.17 %)                           rel step time 0.80
Solve-SymmClashes-Aux$1?1 (2023) -> 20552443 (1.03 %, += 43.20 %)                   rel step time 1.25
Solve-SymmClashes-Aux$7?1 (2023) -> 20552216 (1.03 %, += 44.23 %)                   rel step time 1.50
Solve-SymmClashes-Aux$6?1 (2023) -> 20552216 (1.03 %, += 45.26 %)                   rel step time 1.25
Solve-SymmClashes-Aux$5?1 (2023) -> 20552216 (1.03 %, += 46.28 %)                   rel step time 1.33
Solve-SymmClashes-Aux$4?1 (2023) -> 20552216 (1.03 %, += 47.31 %)                   rel step time 1.54
Solve-SymmClashes-Aux$3?1 (2023) -> 20552216 (1.03 %, += 48.34 %)                   rel step time 1.26
Solve-SymmClashes-Aux$2?1 (2023) -> 20552216 (1.03 %, += 49.37 %)                   rel step time 1.46
Solve-SymmClashes-Aux$8?1 (2023) -> 20552215 (1.03 %, += 50.39 %)                   rel step time 1.24
…

_profile_count.txt

Затраты времени:

Total time: 2961.90700 s
Total semisteps (function calls and closure unwraps): 2000059607
Mean semistep time: 1.480909 us

ClearCoordinates (2023) -> 248532.0 ms (8.39 %, += 8.39 %)                            rel step time 0.58
Solve-SymmClashes-Aux$11?2 (2023) -> 71417.0 ms (2.41 %, += 10.80 %)                  rel step time 2.35
Solve-SymmClashes-Aux$13?2 (2023) -> 68305.0 ms (2.31 %, += 13.11 %)                  rel step time 2.24
Solve-SymmClashes-Aux$9?1 (2023) -> 63106.0 ms (2.13 %, += 15.24 %)                   rel step time 2.07
RemoveTautologies\1 (2023) -> 58887.0 ms (1.99 %, += 17.23 %)                         rel step time 0.97
Solve-SymmClashes-Aux$40?2 (2023) -> 49034.0 ms (1.66 %, += 18.88 %)                  rel step time 1.61
Solve-SymmClashes-Aux$39?1 (2023) -> 47462.0 ms (1.60 %, += 20.48 %)                  rel step time 1.56
Solve-SymmClashes-Aux$48?1 (2023) -> 47105.0 ms (1.59 %, += 22.08 %)                  rel step time 1.55
Solve-SymmClashes-Aux$4?1 (2023) -> 46943.0 ms (1.58 %, += 23.66 %)                   rel step time 1.54
Solve-SymmClashes-Aux$46?1 (2023) -> 46894.0 ms (1.58 %, += 25.24 %)                  rel step time 1.54
Solve-SymmClashes-Aux$28?1 (2023) -> 46363.0 ms (1.57 %, += 26.81 %)                  rel step time 1.52
Solve-SymmClashes-Aux$44?1 (2023) -> 46183.0 ms (1.56 %, += 28.37 %)                  rel step time 1.52
Solve-SymmClashes-Aux$43?1 (2023) -> 46148.0 ms (1.56 %, += 29.93 %)                  rel step time 1.52
Solve-SymmClashes-Aux$18?1 (2023) -> 46102.0 ms (1.56 %, += 31.48 %)                  rel step time 1.51
Solve-SymmClashes-Aux$26?1 (2023) -> 45971.0 ms (1.55 %, += 33.03 %)                  rel step time 1.51
Solve-SymmClashes-Aux$7?1 (2023) -> 45664.0 ms (1.54 %, += 34.58 %)                   rel step time 1.50
SeparateTermLeft (2023) -> 45426.0 ms (1.53 %, += 36.11 %)                            rel step time 0.75
Solve-SymmClashes-Aux$30?1 (2023) -> 44544.0 ms (1.50 %, += 37.61 %)                  rel step time 1.46
Solve-SymmClashes-Aux$32?1 (2023) -> 44388.0 ms (1.50 %, += 39.11 %)                  rel step time 1.46
Solve-SymmClashes-Aux$2?1 (2023) -> 44363.0 ms (1.50 %, += 40.61 %)                   rel step time 1.46
Solve-SymmClashes-Aux$22?1 (2023) -> 44362.0 ms (1.50 %, += 42.11 %)                  rel step time 1.46
Solve-SymmClashes-Aux$24?1 (2023) -> 44293.0 ms (1.50 %, += 43.60 %)                  rel step time 1.46
IsTerm (2023) -> 43100.0 ms (1.46 %, += 45.06 %)                                      rel step time 0.70
Solve-SymmClashes-Aux$20?1 (2023) -> 43056.0 ms (1.45 %, += 46.51 %)                  rel step time 1.41
Solve-SymmClashes-Aux$5?1 (2023) -> 40483.0 ms (1.37 %, += 47.88 %)                   rel step time 1.33
Solve-SymmClashes-Aux$49?1 (2023) -> 40449.0 ms (1.37 %, += 49.24 %)                  rel step time 1.33
Solve-SymmClashes-Aux$45?1 (2023) -> 39963.0 ms (1.35 %, += 50.59 %)                  rel step time 1.31
…

Очевидно, это та же проблема, что и описанная в 40b525fe60164085c14a514ec67fb8ce6740e775 применительно к Solve-Clashes. А значит, она требует то же решение.

Mazdaywik avatar Aug 08 '21 06:08 Mazdaywik