jQuery takes over a minute to load in dev

performance

(Theron Boerner) #1

Is this normal?


(Robin Ward) #2

Absolutely not! Although depending on your setup, the first time you request the site in development mode it can be quite slow. On subsequent loads is it sitll taking over a minute?


(Theron Boerner) #3

Yes. Here’s the log:

[vagrant@precise32:/vagrant (master)]$ rails s
=> Booting Thin
=> Rails 4.1.8 application starting in development on http://0.0.0.0:3000
=> Run `rails server -h` for more startup options
=> Notice: server is listening on all interfaces (0.0.0.0). Consider using 127.0.0.1 (--binding option)
=> Ctrl-C to shutdown server
Thin web server (v1.6.2 codename Doc Brown)
Maximum connections set to 1024
Listening on 0.0.0.0:3000, CTRL+C to stop
D, [2015-01-14T14:20:49.361582 #3330] DEBUG -- :
D, [2015-01-14T14:20:49.361772 #3330] DEBUG -- :
I, [2015-01-14T14:20:49.362090 #3330]  INFO -- : Started GET "/" for 10.0.2.2 at 2015-01-14 14:20:49 -0500
D, [2015-01-14T14:20:49.803670 #3330] DEBUG -- :   ActiveRecord::SchemaMigration Load (1.7ms)  SELECT "schema_migrations".* FROM "schema_migrations"
I, [2015-01-14T14:20:49.912238 #3330]  INFO -- : Processing by ListController#latest as HTML
D, [2015-01-14T14:20:50.869656 #3330] DEBUG -- :   Group Load (1.9ms)  SELECT "groups".* FROM "groups"   ORDER BY "groups"."name" ASC
D, [2015-01-14T14:20:50.888435 #3330] DEBUG -- :   Category Load (1.7ms)  SELECT "categories".* FROM "categories"  WHERE (NOT categories.read_restricted)  ORDER BY "categories"."position" ASC
D, [2015-01-14T14:20:50.939828 #3330] DEBUG -- :   Topic Load (2.0ms)  SELECT id, title, slug FROM "topics"  WHERE ("topics"."deleted_at" IS NULL) AND "topics"."id" IN (56, 10, 11, 12, 13, 41, 42, 43, 44, 45, 46, 47)
D, [2015-01-14T14:20:50.977883 #3330] DEBUG -- :    (1.3ms)  SELECT "categories"."id" FROM "categories"  WHERE (1=0)
D, [2015-01-14T14:20:50.988757 #3330] DEBUG -- :   PostActionType Load (1.4ms)  SELECT "post_action_types".* FROM "post_action_types"   ORDER BY position asc
D, [2015-01-14T14:20:51.010938 #3330] DEBUG -- :   PostActionType Load (1.9ms)  SELECT "post_action_types".* FROM "post_action_types"  WHERE "post_action_types"."name_key" IN ('inappropriate', 'spam', 'notify_moderators')  ORDER BY position asc
D, [2015-01-14T14:20:51.021434 #3330] DEBUG -- :   UserField Load (1.8ms)  SELECT "user_fields".* FROM "user_fields"
D, [2015-01-14T14:20:51.040000 #3330] DEBUG -- :   SiteCustomization Load (1.3ms)  SELECT "site_customizations".* FROM "site_customizations"  WHERE "site_customizations"."enabled" = 't'  ORDER BY "site_customizations"."name" ASC
D, [2015-01-14T14:20:51.058570 #3330] DEBUG -- :   CACHE (0.0ms)  SELECT "site_customizations".* FROM "site_customizations"  WHERE "site_customizations"."enabled" = 't'  ORDER BY "site_customizations"."name" ASC
D, [2015-01-14T14:20:51.066524 #3330] DEBUG -- :   Topic Load (1.8ms)  SELECT  "topics".* FROM "topics"  WHERE ("topics"."deleted_at" IS NULL) AND "topics"."archetype" = 'banner'  ORDER BY "topics"."id" ASC LIMIT 1
D, [2015-01-14T14:20:51.081672 #3330] DEBUG -- :    (1.7ms)  SELECT "categories"."id" FROM "categories"  WHERE "categories"."read_restricted" = 'f'
D, [2015-01-14T14:20:51.124738 #3330] DEBUG -- :   SQL (4.0ms)  SELECT  "topics"."id" AS t0_r0, "topics"."title" AS t0_r1, "topics"."last_posted_at" AS t0_r2, "topics"."created_at" AS t0_r3, "topics"."updated_at" AS t0_r4, "topics"."views" AS t0_r5, "topics"."posts_count" AS t0_r6, "topics"."user_id" AS t0_r7, "topics"."last_post_user_id" AS t0_r8, "topics"."reply_count" AS t0_r9, "topics"."featured_user1_id" AS t0_r10, "topics"."featured_user2_id" AS t0_r11, "topics"."featured_user3_id" AS t0_r12, "topics"."avg_time" AS t0_r13, "topics"."deleted_at" AS t0_r14, "topics"."highest_post_number" AS t0_r15, "topics"."image_url" AS t0_r16, "topics"."off_topic_count" AS t0_r17, "topics"."like_count" AS t0_r18, "topics"."incoming_link_count" AS t0_r19, "topics"."bookmark_count" AS t0_r20, "topics"."category_id" AS t0_r21, "topics"."visible" AS t0_r22, "topics"."moderator_posts_count" AS t0_r23, "topics"."closed" AS t0_r24, "topics"."archived" AS t0_r25, "topics"."bumped_at" AS t0_r26, "topics"."has_summary" AS t0_r27, "topics"."vote_count" AS t0_r28, "topics"."archetype" AS t0_r29, "topics"."featured_user4_id" AS t0_r30, "topics"."notify_moderators_count" AS t0_r31, "topics"."spam_count" AS t0_r32, "topics"."illegal_count" AS t0_r33, "topics"."inappropriate_count" AS t0_r34, "topics"."pinned_at" AS t0_r35, "topics"."score" AS t0_r36, "topics"."percent_rank" AS t0_r37, "topics"."notify_user_count" AS t0_r38, "topics"."subtype" AS t0_r39, "topics"."slug" AS t0_r40, "topics"."auto_close_at" AS t0_r41, "topics"."auto_close_user_id" AS t0_r42, "topics"."auto_close_started_at" AS t0_r43, "topics"."deleted_by_id" AS t0_r44, "topics"."participant_count" AS t0_r45, "topics"."word_count" AS t0_r46, "topics"."excerpt" AS t0_r47, "topics"."pinned_globally" AS t0_r48, "topics"."auto_close_based_on_last_post" AS t0_r49, "topics"."auto_close_hours" AS t0_r50, "categories"."id" AS t1_r0, "categories"."name" AS t1_r1, "categories"."color" AS t1_r2, "categories"."topic_id" AS t1_r3, "categories"."topic_count" AS t1_r4, "categories"."created_at" AS t1_r5, "categories"."updated_at" AS t1_r6, "categories"."user_id" AS t1_r7, "categories"."topics_year" AS t1_r8, "categories"."topics_month" AS t1_r9, "categories"."topics_week" AS t1_r10, "categories"."slug" AS t1_r11, "categories"."description" AS t1_r12, "categories"."text_color" AS t1_r13, "categories"."read_restricted" AS t1_r14, "categories"."auto_close_hours" AS t1_r15, "categories"."post_count" AS t1_r16, "categories"."latest_post_id" AS t1_r17, "categories"."latest_topic_id" AS t1_r18, "categories"."position" AS t1_r19, "categories"."parent_category_id" AS t1_r20, "categories"."posts_year" AS t1_r21, "categories"."posts_month" AS t1_r22, "categories"."posts_week" AS t1_r23, "categories"."email_in" AS t1_r24, "categories"."email_in_allow_strangers" AS t1_r25, "categories"."topics_day" AS t1_r26, "categories"."posts_day" AS t1_r27, "categories"."logo_url" AS t1_r28, "categories"."background_url" AS t1_r29, "categories"."allow_badges" AS t1_r30, "categories"."name_lower" AS t1_r31, "categories"."auto_close_based_on_last_post" AS t1_r32 FROM "topics" LEFT OUTER JOIN "categories" ON "categories"."id" = "topics"."category_id" WHERE (topics.archetype <> 'private_message') AND (COALESCE(categories.topic_id, 0) <> topics.id) AND "topics"."visible" = 't' AND (topics.deleted_at IS NULL) AND (topics.category_id IS NULL or topics.category_id IN (3,5,6,7,8,9,10,11,14,4,2,1,12))  ORDER BY CASE WHEN topics.pinned_globally AND (topics.pinned_at IS NOT NULL) THEN 0 ELSE 1 END, topics.bumped_at DESC LIMIT 30
D, [2015-01-14T14:20:51.138177 #3330] DEBUG -- :   User Load (1.7ms)  SELECT "users"."id", "users"."email", "users"."username", "users"."uploaded_avatar_id" FROM "users"  WHERE "users"."id" IN (24, 7, 23, 19, 22, 2, 20, 22, 11, 20, 14, 9, 20, 11, 12)
I, [2015-01-14T14:20:51.216438 #3330]  INFO -- :   Rendered list/list.erb within layouts/application (18.0ms)
I, [2015-01-14T14:20:51.257442 #3330]  INFO -- :   Rendered common/_special_font_face.html.erb (16.1ms)
D, [2015-01-14T14:20:51.276384 #3330] DEBUG -- :   ColorScheme Load (1.7ms)  SELECT  "color_schemes".* FROM "color_schemes"  WHERE "color_schemes"."versioned_id" IS NULL AND "color_schemes"."enabled" = 't' LIMIT 1
D, [2015-01-14T14:20:51.282342 #3330] DEBUG -- :    (2.4ms)  SELECT  "categories"."updated_at" FROM "categories"   ORDER BY updated_at desc LIMIT 1
D, [2015-01-14T14:20:51.301222 #3330] DEBUG -- :    (1.7ms)  SELECT "site_customizations"."stylesheet_baked" FROM "site_customizations"  WHERE "site_customizations"."enabled" = 't'  ORDER BY "site_customizations"."name" ASC
I, [2015-01-14T14:20:51.306716 #3330]  INFO -- :   Rendered common/_discourse_stylesheet.html.erb (44.9ms)
I, [2015-01-14T14:20:51.313313 #3330]  INFO -- :   Rendered layouts/_head.html.erb (85.7ms)
D, [2015-01-14T14:20:56.095943 #3330] DEBUG -- :   CACHE (0.0ms)  SELECT "site_customizations".* FROM "site_customizations"  WHERE "site_customizations"."enabled" = 't'  ORDER BY "site_customizations"."name" ASC
D, [2015-01-14T14:20:56.102536 #3330] DEBUG -- :   CACHE (0.0ms)  SELECT "site_customizations".* FROM "site_customizations"  WHERE "site_customizations"."enabled" = 't'  ORDER BY "site_customizations"."name" ASC
I, [2015-01-14T14:20:56.120589 #3330]  INFO -- :   Rendered common/_discourse_javascript.html.erb (11.1ms)
D, [2015-01-14T14:20:56.123977 #3330] DEBUG -- :   CACHE (0.0ms)  SELECT "site_customizations".* FROM "site_customizations"  WHERE "site_customizations"."enabled" = 't'  ORDER BY "site_customizations"."name" ASC
I, [2015-01-14T14:20:56.129437 #3330]  INFO -- : Completed 200 OK in 6215ms (Views: 4928.7ms | ActiveRecord: 60.3ms)
F, [2015-01-14T14:21:04.730695 #3330] FATAL -- :
ActionController::RoutingError (No route matches [GET] "/letter_avatar/pekka.gaiser/50/2.png"):
  config/initializers/silence_logger.rb:24:in `call'
  lib/middleware/missing_avatars.rb:21:in `call'
  lib/middleware/turbo_dev.rb:32:in `call'

And console

ember.js:3936 DEBUG: -------------------------------
ember.js:3936 DEBUG: Ember      : 1.9.0
ember.js:3936 DEBUG: Handlebars : 2.0.0
ember.js:3936 DEBUG: jQuery     : 2.1.1
ember.js:3936 DEBUG: -------------------------------
http://localhost:4000/letter_avatar/pekka.gaiser/50/2.png Failed to load resource: the server responded with a status of 404 (Not Found)
http://localhost:4000/ Failed to load resource: net::ERR_CACHE_MISS