E.g. GET for /ems_container/new
takes 3–9 seconds — before loading any linked assets!
Is it "standard developement mode slowness"? Feels unreasonable for just loading an empty form, would like to understand.
Around that time, timeline shows couple >1second "Parse HTML" which actually constists of running JS -> miqBootstrap...
[----] D, [2017-01-04T16:23:33.151067 #13684:2aabaf6240f0] DEBUG -- : PostgreSQLAdapter#log_after_checkin, connection_pool: size: 5, connections: 5, in use: 0, waiting_in_queue: 0
[----] D, [2017-01-04T16:23:34.738222 #13684:3faf3a003f24] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 5, connections: 5, in use: 1, waiting_in_queue: 0
[----] I, [2017-01-04T16:23:34.739324 #13684:3faf3a003f24] INFO -- : Started GET "/ems_container/new" for ::1 at 2017-01-04 16:23:34 +0200
[----] I, [2017-01-04T16:23:34.881941 #13684:3faf3a003f24] INFO -- : Processing by EmsContainerController#new as HTML
[----] D, [2017-01-04T16:23:34.909980 #13684:3faf3a003f24] DEBUG -- : User Load (3.9ms) SELECT "users".* FROM "users" WHERE ("users"."id" BETWEEN $1 AND $2) AND "users"."userid" = $3 LIMIT $4 [["id", 0], ["id", 999999999999], ["userid", "admin"], ["LIMIT", 1]]
[----] D, [2017-01-04T16:23:34.914627 #13684:3faf3a003f24] DEBUG -- : User Inst Including Associations (1.8ms - 1rows)
[----] D, [2017-01-04T16:23:34.927031 #13684:3faf3a003f24] DEBUG -- : MiqGroup Load (2.2ms) SELECT "miq_groups".* FROM "miq_groups" WHERE "miq_groups"."id" = $1 LIMIT $2 [["id", 2], ["LIMIT", 1]]
[----] D, [2017-01-04T16:23:34.930932 #13684:3faf3a003f24] DEBUG -- : MiqGroup Inst Including Associations (2.4ms - 1rows)
[----] D, [2017-01-04T16:23:34.947414 #13684:3faf3a003f24] DEBUG -- : Tenant Load (1.7ms) SELECT "tenants".* FROM "tenants" WHERE "tenants"."id" = $1 LIMIT $2 [["id", 1], ["LIMIT", 1]]
[----] D, [2017-01-04T16:23:34.948427 #13684:3faf3a003f24] DEBUG -- : Tenant Inst Including Associations (0.4ms - 1rows)
[----] D, [2017-01-04T16:23:34.962532 #13684:3faf3a003f24] DEBUG -- : MiqUserRole Load (1.3ms) SELECT "miq_user_roles".* FROM "miq_user_roles" INNER JOIN "entitlements" ON "miq_user_roles"."id" = "entitlements"."miq_user_role_id" WHERE "entitlements"."miq_group_id" = $1 LIMIT $2 [["miq_group_id", 2], ["LIMIT", 1]]
[----] D, [2017-01-04T16:23:34.966377 #13684:3faf3a003f24] DEBUG -- : MiqUserRole Inst Including Associations (1.5ms - 1rows)
[----] D, [2017-01-04T16:23:34.984036 #13684:3faf3a003f24] DEBUG -- : MiqProductFeature Load (4.5ms) SELECT "miq_product_features".* FROM "miq_product_features" INNER JOIN "miq_roles_features" ON "miq_product_features"."id" = "miq_roles_features"."miq_product_feature_id" WHERE "miq_roles_features"."miq_user_role_id" = $1 [["miq_user_role_id", 1]]
[----] D, [2017-01-04T16:23:34.987674 #13684:3faf3a003f24] DEBUG -- : MiqProductFeature Inst Including Associations (2.3ms - 1rows)
[----] D, [2017-01-04T16:23:35.009070 #13684:3faf3a003f24] DEBUG -- : Zone Load (3.6ms) SELECT "zones".* FROM "zones" ORDER BY lower(description)
[----] D, [2017-01-04T16:23:35.009768 #13684:3faf3a003f24] DEBUG -- : Zone Inst Including Associations (0.2ms - 1rows)
[----] D, [2017-01-04T16:23:35.012825 #13684:3faf3a003f24] DEBUG -- : (0.4ms) SELECT "providers"."name", "providers"."id" FROM "providers" WHERE "providers"."type" IN ('ManageIQ::Providers::Openstack::Provider')
[----] D, [2017-01-04T16:23:35.034810 #13684:3faf3a003f24] DEBUG -- : CACHE (0.4ms) SELECT "zones".* FROM "zones" ORDER BY lower(description)
[----] D, [2017-01-04T16:23:35.035476 #13684:3faf3a003f24] DEBUG -- : Zone Inst Including Associations (0.1ms - 1rows)
[----] D, [2017-01-04T16:23:35.047611 #13684:3faf3a003f24] DEBUG -- : ManageIQ::Providers::Openstack::Provider Load (2.0ms) SELECT "providers".* FROM "providers" WHERE "providers"."type" IN ('ManageIQ::Providers::Openstack::Provider') ORDER BY lower(name)
[----] D, [2017-01-04T16:23:35.050584 #13684:3faf3a003f24] DEBUG -- : ManageIQ::Providers::Openstack::Provider Inst Including Associations (0.1ms - 0rows)
[----] I, [2017-01-04T16:23:35.059027 #13684:3faf3a003f24] INFO -- : Rendering /home/bpaskinc/miq/manageiq-ui-classic/app/views/ems_container/new.html.haml within layouts/application
[----] I, [2017-01-04T16:23:35.061917 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_flash_msg.html.haml (0.1ms)
[----] I, [2017-01-04T16:23:35.067094 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular-bootstrap/_endpoints_angular.html.haml (1.7ms)
[----] I, [2017-01-04T16:23:35.071626 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_form_buttons_verify_angular.html.haml (0.5ms)
[----] I, [2017-01-04T16:23:35.071957 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular-bootstrap/_auth_credentials_angular_bootstrap.html.haml (3.4ms)
[----] I, [2017-01-04T16:23:35.076233 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_form_buttons_verify_angular.html.haml (0.5ms)
[----] I, [2017-01-04T16:23:35.076519 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_auth_service_account_angular.html.haml (3.3ms)
[----] I, [2017-01-04T16:23:35.084601 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular-bootstrap/_endpoints_angular.html.haml (6.5ms)
[----] I, [2017-01-04T16:23:35.093502 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular-bootstrap/_endpoints_angular.html.haml (3.0ms)
[----] I, [2017-01-04T16:23:35.096510 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_form_buttons_verify_angular.html.haml (0.3ms)
[----] I, [2017-01-04T16:23:35.096792 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular-bootstrap/_auth_credentials_angular_bootstrap.html.haml (1.9ms)
[----] I, [2017-01-04T16:23:35.100037 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_form_buttons_verify_angular.html.haml (0.4ms)
[----] I, [2017-01-04T16:23:35.100335 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular-bootstrap/_auth_credentials_angular_bootstrap.html.haml (2.2ms)
[----] I, [2017-01-04T16:23:35.110479 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_form_buttons_verify_angular.html.haml (1.0ms)
[----] I, [2017-01-04T16:23:35.114273 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular-bootstrap/_auth_credentials_angular_bootstrap.html.haml (9.3ms)
[----] I, [2017-01-04T16:23:35.124857 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular-bootstrap/_endpoints_angular.html.haml (3.6ms)
[----] I, [2017-01-04T16:23:35.131805 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_form_buttons_verify_angular.html.haml (1.3ms)
[----] I, [2017-01-04T16:23:35.133796 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_multi_auth_credentials.html.haml (69.7ms)
[----] I, [2017-01-04T16:23:35.140605 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/angular/_x_edit_buttons_angular.html.haml (2.6ms)
[----] I, [2017-01-04T16:23:35.141532 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/ems_container/_form.html.haml (80.5ms)
[----] I, [2017-01-04T16:23:35.144816 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/ems_container/new.html.haml within layouts/application (85.1ms)
[----] I, [2017-01-04T16:23:35.152028 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_doctype.html.haml (0.5ms)
[----] I, [2017-01-04T16:23:35.668647 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/stylesheets/_template50.html.haml (0.1ms)
[----] I, [2017-01-04T16:23:37.613053 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_i18n_js.html.haml (0.5ms)
[----] I, [2017-01-04T16:23:37.631720 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_about_modal.html.haml (12.3ms)
[----] D, [2017-01-04T16:23:37.662229 #13684:3faf3a003f24] DEBUG -- : MiqGroup Load (5.0ms) SELECT "miq_groups".* FROM "miq_groups" INNER JOIN "miq_groups_users" ON "miq_groups"."id" = "miq_groups_users"."miq_group_id" WHERE "miq_groups_users"."user_id" = $1 [["user_id", 1]]
[----] D, [2017-01-04T16:23:37.666294 #13684:3faf3a003f24] DEBUG -- : MiqGroup Inst Including Associations (2.5ms - 1rows)
[----] I, [2017-01-04T16:23:37.670259 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_user_options.html.haml (26.2ms)
[----] I, [2017-01-04T16:23:37.671624 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_spinner.html.haml (0.1ms)
[----] I, [2017-01-04T16:23:37.672949 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_lightbox_panel.html.haml (0.1ms)
[----] I, [2017-01-04T16:23:37.676480 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_notifications_drawer.html.haml (1.0ms)
[----] I, [2017-01-04T16:23:37.680316 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_toast_list.html.haml (0.4ms)
[----] I, [2017-01-04T16:23:37.681372 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_header.html.haml (64.7ms)
[----] D, [2017-01-04T16:23:37.719558 #13684:3faf3a003f24] DEBUG -- : (3.2ms) SELECT "ext_management_systems"."id" FROM "ext_management_systems" WHERE "ext_management_systems"."type" IN ('ManageIQ::Providers::Openstack::InfraManager')
[----] D, [2017-01-04T16:23:37.726315 #13684:3faf3a003f24] DEBUG -- : CACHE (0.3ms) SELECT "ext_management_systems"."id" FROM "ext_management_systems" WHERE "ext_management_systems"."type" IN ('ManageIQ::Providers::Openstack::InfraManager')
[----] I, [2017-01-04T16:23:37.761911 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_vertical_navbar.html.haml (75.2ms)
[----] I, [2017-01-04T16:23:37.764116 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_breadcrumbs.html.haml (0.1ms)
[----] I, [2017-01-04T16:23:37.768922 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_tabs.html.haml (0.8ms)
[----] I, [2017-01-04T16:23:37.771488 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_content.html.haml (86.9ms)
[----] I, [2017-01-04T16:23:37.779658 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_adv_search.html.haml (0.5ms)
[----] I, [2017-01-04T16:23:37.820526 #13684:3faf3a003f24] INFO -- : Rendered /home/bpaskinc/miq/manageiq-ui-classic/app/views/layouts/_footer.html.haml (44.8ms)
[----] D, [2017-01-04T16:23:44.590627 #13684:3faedcd83c0c] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 5, connections: 5, in use: 3, waiting_in_queue: 0
Session: Hash of Size 11809, Elements 31
=================================[----] I, [2017-01-04T16:23:44.616863 #13684:3faedcd83c0c] INFO -- : Finished "/ws/notifications" [WebSocket] for ::1 at 2017-01-04 16:23:44 +0200
[----] I, [2017-01-04T16:23:44.618004 #13684:3faedcd83c0c] INFO -- : NotificationChannel stopped streaming from notifications_1
[----] D, [2017-01-04T16:23:44.618467 #13684:3faf3a003e98] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 5, connections: 5, in use: 3, waiting_in_queue: 0
[----] D, [2017-01-04T16:23:44.619814 #13684:3faedcd83c0c] DEBUG -- : PostgreSQLAdapter#log_after_checkin, connection_pool: size: 5, connections: 5, in use: 2, waiting_in_queue: 0
[----] I, [2017-01-04T16:23:44.628717 #13684:3faf3a003e98] INFO -- : Started GET "/ws/notifications" for ::1 at 2017-01-04 16:23:44 +0200
[----] I, [2017-01-04T16:23:44.796030 #13684:3faf3a003f24] INFO -- : Completed 200 OK in 9912ms (Views: 2756.9ms | ActiveRecord: 28.5ms)