简短描述（我们在浏览器调试器网络选项卡中）：
AJAX GET /page/42 takes ~20s
replay/resend this XHR takes ~15s
open this XHR in new tab takes ~1.5s (only!)
replay/resend this XHR takes ~15s (again)
仅发生在开发中
始终（并且跨浏览器）能够重现
导轨 3.2.22.5
HAML 浪费了时间（非常确定）
我正在开发一个 HTML 编辑器来设计打印页面。可以说，这个编辑器是全面的。
开始时，我必须渲染完整的编辑器 HAML（约 1000 行），这需要不到 5 秒的时间（除非在 Rails 启动后首先进行）。这速度相当快。
基本结构如下所示（伪 HAML，每行都是一个部分，数字约为渲染时间）节数 (n) 通常约为 10 到 15
editor_layout
editor (~5s)
edit_background (~1.5s)
the_page (0.1s*n)
section_1
.
.
section_n
dialog_1
dialog_2
.
.
dialog_42
打印时（PDF）它看起来像
print_layout (~1.5s)
the_page (0.1s*n)
section_1
.
.
section_n
到目前为止一切都很好，特别是在开发环境中。
但是当我必须在编辑器中更改页面并使用 AJAX 调用新页面以获取内部 HTML
no_layout
edit_background (~15s)
the_page (1s*n)
section_1
.
.
section_n
该动作大约需要 15 秒（！）。渲染一个部分的时间现在需要 1 秒，而不是 100 毫秒。如果我在新的浏览器选项卡中打开相同的 URL，我会回到通常的 1.5 秒。
我不知道为什么。
更奇怪的是：
我可以使用 AJAX 重新加载（重新渲染）编辑器的任何（HTML）部分，这看起来像
/page/42/edit?inner-html=background, dialog_1, dialog_42
/page/42/edit?inner-html=dialog_5
在这种情况下，编辑器 HAML 会被渲染，但仅渲染所请求的部分，并且如果我请求（AJAX）
/page/42/edit?inner-html=background
我又回到了~2秒！尽管执行了更多更复杂的逻辑。
我不知道在哪里进一步搜索，但我想了解发生了什么。
有什么想法吗？
编辑：放置控制台输出
说明：这些是我在选项卡中多次打开并刷新和重播 XHR 后获取的日志
由于 30k 限制，我不得不删除一些（相同的 SQL-）行
线条看起来像这样
------- start 5 ( 5) [xxxxx number]
是“时间轴”方法的输出。其中 start（在本例中为“start”）只是一个名称，数字是自上次调用以来的时间（毫秒），括号中是迄今为止的时间。可选的“XXXX号码”告诉命名块调用的时间。
比较这两个文件显示“start with paragroup”行中的差异，这是 HAML 中的第一行：
- time_line "start with paragroup"
而“doneprepare_paragroup”或多或少是渲染“paragroup”之前的最后一个
选项卡日志（刷新）
--- render if @ [@]
--- render if message_box - not rendered [@]
Started GET "/ldc/books/288efbc2-98b2-4beb-92de-e5de108cec4d/draw/8fe00ae1-c9d2-4c23-9de3-e7c7ee939fd5?inner=@" for 127.0.0.1 at 2017-08-16 19:31:28 +0300
------- initialize 0 ( 0)
Processing by Ldc::BooksController#draw as HTML
Parameters: {"inner"=>"@", "id"=>"288efbc2-98b2-4beb-92de-e5de108cec4d", "bookpage_id"=>"8fe00ae1-c9d2-4c23-9de3-e7c7ee939fd5"}
say in site_controller.rb:(66) block
------- start --------
------- start 5 ( 5)
LoginData Load (1.0ms) SELECT "login_data".* FROM "login_data" WHERE "login_data"."id" = '0c439950-b8d6-4b8a-9d39-2b2e51a4a291' LIMIT 1
say in checker.rb:(16) initialize
Ldc::Person Load (0.0ms) SELECT "ldc_people".* FROM "ldc_people" WHERE "ldc_people"."ustate" = 'A' AND "ldc_people"."login_data_id" = '0c439950-b8d6-4b8a-9d39-2b2e51a4a291' LIMIT 1
Ldc::Bookpage Load (0.5ms) SELECT "ldc_bookpages".* FROM "ldc_bookpages" WHERE "ldc_bookpages"."ustate" = 'A' AND "ldc_bookpages"."id" = ? LIMIT 1 [["id", "8fe00ae1-c9d2-4c23-9de3-e7c7ee939fd5"]]
------- call ldc/editor/edit_background 1 ( 265)
######
{:locals=>{}}
{:locals=>{}}
------- call ldc/editor/book_page 53 ( 319)
------- start render partial book_page (#<Ldc::PageTemplates::Defau 27 ( 346)
------- --ClassicDefaultDefault---- start bookpage 8fe00ae1-c9d2-4c2 0 ( 346)
------- start to css pre: 0 ( 346)
------- done analyse 0 ( 346)
------- done cibo_template.css 2 ( 348)
------- 555555 1 ( 349)
------- start-1 prepare_paragroup 1 ( 350)
------- in A prepare_paragroup 13 ( 363)
------- done prepare_paragroup 0 ( 363)
------- render partial group: 0 ( 363)
------- start with paragroup 80 ( 443)
(1.0ms) select textable_id as id, role, text
...
------- end with paragroup 12 ( 455)
Rendered ppa_data/templates/classic/default/_dg_tables.haml (29.4ms)
------- done partial group: 1 ( 456) group 93
------- start-1 prepare_paragroup 0 ( 456)
------- in A prepare_paragroup 15 ( 471)
------- done prepare_paragroup 1 ( 472)
------- start with paragroup 66 ( 539)
------- end with paragroup 20 ( 559)
Rendered ppa_data/templates/classic/default/_dg_tables.haml (20.1ms)
------- start-1 prepare_paragroup 0 ( 560)
------- in A prepare_paragroup 16 ( 576)
------- done prepare_paragroup 0 ( 576)
------- start with paragroup 67 ( 643)
------- end with paragroup 7 ( 650)
Rendered ppa_data/templates/classic/default/_dg_tables.haml (7.0ms)
Ldc::Pageelement Load (1.0ms) SELECT "ldc_pageelements".* FROM "ldc_pageelements" WHERE "ldc_pageelements"."ustate" = 'A' AND "ldc_pageelements"."id" = ? LIMIT 1 [["id", "da4584dd-ea18-4f14-a321-1e2628efe0c9"]]
(0.0ms) begin transaction
(1.0ms) UPDATE "ldc_pageelements" SET "element_position" = NULL, "updated_at" = '2017-08-16 16:31:29.294182', "paragroup_order" = '211cfcc6-3ce5-4c3f-b001-2230a76cc8903568750-4cc5-45ca-879e-1fa214921d12' WHERE "ldc_pageelements"."id" = 'da4584dd-ea18-4f14-a321-1e2628efe0c9'
(4.0ms) commit transaction
------- start-1 prepare_paragroup 9 ( 659)
------- in A prepare_paragroup 22 ( 681)
------- done prepare_paragroup 1 ( 682)
------- start with paragroup 64 ( 747)
------- end with paragroup 11 ( 758)
Rendered ppa_data/templates/classic/default/_dg_tables.haml (12.1ms)
Ldc::Pageelement Load (0.0ms) SELECT "ldc_pageelements".* FROM "ldc_pageelements" WHERE "ldc_pageelements"."ustate" = 'A' AND "ldc_pageelements"."id" = ? LIMIT 1 [["id", "a27f1ca2-d136-4aef-a486-24772766c04f"]]
(1.0ms) begin transaction
(1.0ms) UPDATE "ldc_pageelements" SET "element_position" = NULL, "updated_at" = '2017-08-16 16:31:29.403252', "paragroup_order" = 'dd7489ce-0b22-40dc-81ab-072de59b7357' WHERE "ldc_pageelements"."id" = 'a27f1ca2-d136-4aef-a486-24772766c04f'
(5.0ms) commit transaction
Ldc::Pageelement Load (1.0ms) SELECT "ldc_pageelements".* FROM "ldc_pageelements" WHERE "ldc_pageelements"."ustate" = 'A' AND "ldc_pageelements"."id" = ? LIMIT 1 [["id", "9e09e934-50a7-41eb-94df-7355b1d3306c"]]
(0.0ms) begin transaction
(1.0ms) UPDATE "ldc_pageelements" SET "element_position" = NULL, "updated_at" = '2017-08-16 16:31:29.412301', "paragroup_order" = '' WHERE "ldc_pageelements"."id" = '9e09e934-50a7-41eb-94df-7355b1d3306c'
(4.0ms) commit transaction
------- done get_page_elements_html 20 ( 778)
Ldc::Page Load (0.0ms) SELECT "ldc_pages".* FROM "ldc_pages" WHERE "ldc_pages"."ustate" = 'A' AND "ldc_pages"."id" = 'dcc8a707-c1c4-4f68-9973-e4c7f0746546' LIMIT 1
Rendered ldc/editor/_book_page.haml (440.4ms)
------- call ldc/editor/book_page 4 ( 782) page 463
------- start to css pre: 0 ( 782)
------- done analyse 1 ( 783)
------- start to css pre: 0 ( 783)
------- done analyse 8 ( 791)
------- start get_page_editor_bind_data 8 ( 800)
------- start to json 0 ( 800)
------- done to json 1 ( 801)
------- end get_page_editor_bind_data 0 ( 801)
Rendered ldc/editor/_edit_background.haml (493.1ms)
Rendered ldc/editor/edit_background.haml within layouts/site_messages (520.1ms)
Rendered site/_base_dialogs.html.haml (11.6ms)
------- call ldc/editor/edit_background 38 ( 839) edit_backg 573
Completed 200 OK in 836.7ms (Views: 550.4ms | ActiveRecord: 98.9ms)
XHR 日志：
--- render if @ [@]
--- render if message_box - not rendered [@]
Started GET "/ldc/books/288efbc2-98b2-4beb-92de-e5de108cec4d/draw/8fe00ae1-c9d2-4c23-9de3-e7c7ee939fd5?inner=@" for 127.0.0.1 at 2017-08-16 19:34:51 +0300
------- initialize 0 ( 0)
Processing by Ldc::BooksController#draw as HTML
Parameters: {"inner"=>"@", "id"=>"288efbc2-98b2-4beb-92de-e5de108cec4d", "bookpage_id"=>"8fe00ae1-c9d2-4c23-9de3-e7c7ee939fd5"}
say in site_controller.rb:(66) block
------- start --------
------- start 0 ( 0)
LoginData Load (0.0ms) SELECT "login_data".* FROM "login_data" WHERE "login_data"."id" = '0c439950-b8d6-4b8a-9d39-2b2e51a4a291' LIMIT 1
say in checker.rb:(16) initialize
Ldc::Person Load (0.0ms) SELECT "ldc_people".* FROM "ldc_people" WHERE "ldc_people"."ustate" = 'A' AND "ldc_people"."login_data_id" = '0c439950-b8d6-4b8a-9d39-2b2e51a4a291' LIMIT 1
Ldc::Bookpage Load (0.0ms) SELECT "ldc_bookpages".* FROM "ldc_bookpages" WHERE "ldc_bookpages"."ustate" = 'A' AND "ldc_bookpages"."id" = ? LIMIT 1 [["id", "8fe00ae1-c9d2-4c23-9de3-e7c7ee939fd5"]]
------- call ldc/editor/edit_background 0 ( 273)
######
{:locals=>{}}
{:locals=>{}}
------- call ldc/editor/book_page 443 ( 716)
------- start render partial book_page (#<Ldc::PageTemplates::Defau 234 ( 951)
------- --ClassicDefaultDefault---- start bookpage 8fe00ae1-c9d2-4c2 0 ( 951)
------- start to css pre: 0 ( 951)
------- done analyse 0 ( 951)
------- done cibo_template.css 0 ( 951)
------- 555555 15 ( 966)
------- start-1 prepare_paragroup 0 ( 966)
------- in A prepare_paragroup 0 ( 966)
------- done prepare_paragroup 0 ( 966)
------- render partial group: 0 ( 966)
------- start with paragroup 819 ( 1786)
(0.0ms) select textable_id as id, role, text
...
------- end with paragroup 0 ( 1786)
Rendered ppa_data/templates/classic/default/_dg_tables.haml (21.2ms)
------- done partial group: 0 ( 1786) group 819
------- start-1 prepare_paragroup 0 ( 1786)
------- in A prepare_paragroup 15 ( 1802)
------- done prepare_paragroup 0 ( 1802)
------- start with paragroup 795 ( 2597)
------- end with paragroup 15 ( 2613)
Rendered ppa_data/templates/classic/default/_dg_tables.haml (15.7ms)
------- start-1 prepare_paragroup 0 ( 2613)
------- in A prepare_paragroup 15 ( 2629)
------- done prepare_paragroup 0 ( 2629)
------- start with paragroup 776 ( 3405)
------- end with paragroup 15 ( 3421)
Rendered ppa_data/templates/classic/default/_dg_tables.haml (15.6ms)
Ldc::Pageelement Load (0.0ms) SELECT "ldc_pageelements".* FROM "ldc_pageelements" WHERE "ldc_pageelements"."ustate" = 'A' AND "ldc_pageelements"."id" = ? LIMIT 1 [["id", "da4584dd-ea18-4f14-a321-1e2628efe0c9"]]
(0.0ms) begin transaction
(0.0ms) UPDATE "ldc_pageelements" SET "element_position" = NULL, "updated_at" = '2017-08-16 16:34:55.110874', "paragroup_order" = '211cfcc6-3ce5-4c3f-b001-2230a76cc8903568750-4cc5-45ca-879e-1fa214921d12' WHERE "ldc_pageelements"."id" = 'da4584dd-ea18-4f14-a321-1e2628efe0c9'
(15.6ms) commit transaction
------- start-1 prepare_paragroup 15 ( 3436)
------- in A prepare_paragroup 15 ( 3452)
------- done prepare_paragroup 15 ( 3468)
------- start with paragroup 753 ( 4221)
------- end with paragroup 15 ( 4237)
Rendered ppa_data/templates/classic/default/_dg_tables.haml (15.6ms)
Ldc::Pageelement Load (0.0ms) SELECT "ldc_pageelements".* FROM "ldc_pageelements" WHERE "ldc_pageelements"."ustate" = 'A' AND "ldc_pageelements"."id" = ? LIMIT 1 [["id", "a27f1ca2-d136-4aef-a486-24772766c04f"]]
(0.0ms) begin transaction
(0.0ms) UPDATE "ldc_pageelements" SET "element_position" = NULL, "updated_at" = '2017-08-16 16:34:55.927238', "paragroup_order" = 'dd7489ce-0b22-40dc-81ab-072de59b7357' WHERE "ldc_pageelements"."id" = 'a27f1ca2-d136-4aef-a486-24772766c04f'
(15.6ms) commit transaction
Ldc::Pageelement Load (0.0ms) SELECT "ldc_pageelements".* FROM "ldc_pageelements" WHERE "ldc_pageelements"."ustate" = 'A' AND "ldc_pageelements"."id" = ? LIMIT 1 [["id", "9e09e934-50a7-41eb-94df-7355b1d3306c"]]
(0.0ms) begin transaction
(0.0ms) UPDATE "ldc_pageelements" SET "element_position" = NULL, "updated_at" = '2017-08-16 16:34:55.942873', "paragroup_order" = '' WHERE "ldc_pageelements"."id" = '9e09e934-50a7-41eb-94df-7355b1d3306c'
(0.0ms) commit transaction
------- done get_page_elements_html 15 ( 4253)
Ldc::Page Load (0.0ms) SELECT "ldc_pages".* FROM "ldc_pages" WHERE "ldc_pages"."ustate" = 'A' AND "ldc_pages"."id" = 'dcc8a707-c1c4-4f68-9973-e4c7f0746546' LIMIT 1
Rendered ldc/editor/_book_page.haml (3301.8ms)
------- call ldc/editor/book_page 0 ( 4253) page 3536
------- start to css pre: 0 ( 4253)
------- done analyse 0 ( 4253)
------- start to css pre: 0 ( 4253)
------- done analyse 15 ( 4268)
------- start get_page_editor_bind_data 0 ( 4268)
------- start to json 0 ( 4268)
------- done to json 0 ( 4268)
------- end get_page_editor_bind_data 0 ( 4268)
Rendered ldc/editor/_edit_background.haml (3574.3ms)
Rendered ldc/editor/edit_background.haml within layouts/site_messages (3825.1ms)
Rendered site/_base_dialogs.html.haml (0.0ms)
------- call ldc/editor/edit_background 238 ( 4507) edit_backg 4233
Completed 200 OK in 4507.1ms (Views: 4202.6ms | ActiveRecord: 90.6ms)
这似乎是 https://github.com/tmm1/stackprof
的工作我会编写一个或 3 个测试（并删除浏览器 - 只需使用标准测试工具）并在其上运行 stackprof。