What is the reason, that rendering same HAML is much slower when ajax than loading in Browser

Question

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 (#



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 (#

What is the reason, that rendering same HAML is much slower when ajax than loading in Browser

0 Answers