Short description (we are in browsers debugger network tab):
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)
Happens in development only
is always (and cross browser) reproduce able
Rails 3.2.22.5
Time is lost in HAML (very sure)
I am working on an HTML editor to design pages for printing. This editor is - let's say - comprehensive.
When starting I have to render the complete editors HAML (~ 1000 lines) this takes less than 5s (unless first after rails start). This is fairly fast.
The basic structure looks like this (pseudo HAML, each line is a partial, numbers are ~rendering time) section count (n) is typically around 10 to 15
editor_layout
editor (~5s)
edit_background (~1.5s)
the_page (0.1s*n)
section_1
.
.
section_n
dialog_1
dialog_2
.
.
dialog_42
when printing (PDF) it looks like
print_layout (~1.5s)
the_page (0.1s*n)
section_1
.
.
section_n
So far so good and OK especially while in a development environment.
But when I have to change the page in editor and call the new page with AJAX to get just the inner HTML
no_layout
edit_background (~15s)
the_page (1s*n)
section_1
.
.
section_n
the action takes about 15s (!). The time comes from rendering a section takes now 1 second instead of 100ms. If I open the same URL in a new browser tab I am back to the usual 1.5 seconds.
I have no idea why.
To make it even weirder:
I can reload (re-render) any (HTML) part of the editor with AJAX, this looks like
/page/42/edit?inner-html=background, dialog_1, dialog_42
/page/42/edit?inner-html=dialog_5
In this case, the editor HAML is rendered but only the part(s) requested, and if I request (AJAX)
/page/42/edit?inner-html=background
I am back to ~2 seconds! although there is much more and complex logic executed.
I have no idea where to search further, but I want to understand whats going on.
Any ideas?
EDIT: put the console output
Explanation: these to logs I took after several open in tab and refresh and replay XHR
I had to delete some (identical SQL-) lines because of 30k limit
lines looking like this
------- start 5 ( 5) [xxxxx number]
are the output of a "timeline" method. Where start (in this case 'start') is just a name, the number is the time (ms) since the last call and in parenthesis is the time so far. The optional "XXXX number" tells the time for a named block call.
Comparing these two files shows the difference in line "start with paragroup" and this is the first line in HAML:
- time_line "start with paragroup"
while "done prepare_paragroup" is more or less the last before rendering "paragroup"
log of the tab(refresh)
--- 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)
log of 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)