Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Already on GitHub? Sign in to your account

Model bundling took longer than 1000 ms #80

Closed
lefnire opened this Issue Jan 15, 2013 · 10 comments

Comments

Projects
None yet
2 participants
Owner

lefnire commented Jan 15, 2013

Honing in on whatever it is that's causing all these bugs.

2013-01-15T20:02:38+00:00 app[web.1]: timers.js:103
2013-01-15T20:02:38+00:00 app[web.1]:             if (!process.listeners('uncaughtException').length) throw e;
2013-01-15T20:02:38+00:00 app[web.1]:                                                                       ^
2013-01-15T20:02:38+00:00 app[web.1]: Error: Model bundling took longer than 1000 ms
2013-01-15T20:02:38+00:00 app[web.1]:     at Object.onBundleTimeout [as _onTimeout] (/app/node_modules/racer/lib/bundle/bundle.Model.js:63:9)
2013-01-15T20:02:38+00:00 app[web.1]:     at Timer.list.ontimeout (timers.js:101:19)
Owner

lefnire commented Jan 18, 2013

unfortunately, difficult to test locally - probably need a load-testing tool, as it seems to only happen under heavy load

it has something with "user" model particularly. I keep constantly catching that error while trying to make more then one "user.set()" in app-routes in my /src/app/controller.coffee (code structure from https://github.com/switz/derby-boilerplate )

  game: (page, model, {gameId}) ->
    console.log "> User: #{userId}    Game: #{gameId}"
    model.subscribe "games.#{gameId}", "users.#{userId}", (err, game, user) ->
      console.log user.get()
      model.ref '_user', user
      model.ref '_game', game
      user.set 'char', 'knight'   # this user.set() alone working all right
      user.set 'color', 'red'       # but if I add one more, it fails with that error
      page.render 'game'

So as a workaround I'm setting all required data to user model through one complex object

user.set 'config', {
  'char': 'knight'
  'color': 'red'
}

I have tested it with other paths, like "games.#{gameId}", and it working ok with any number of game.set()

Owner

lefnire commented Jan 18, 2013

Shoot. That strategy works for initial object creation, but if you're trying to update an existing object, any view-model bindings and model.on -subscriptions for deep attributes get busted.

So for your example, if you had {_user.config.char} in your view, and you attempted a later mass-assignment update with:

update = user.get()
update.config.char = 'pawn'
update.config.color = 'blue'
user.set('config', update.config)

Then your view wouldn't update {_user.config.char}. I imagine there's some connection setup between the variable reference and the view, which gets clobbered once a deep document is replaced whole-sale.

I tried this method by changing my many-set code here into a mass-assignment operation here - none of the subscriptions were triggered, such as auto-updating {_user.stats.hp} in the view or model.on('set', '_user.stats.exp',...)

So in conclusion! We need a model.update() function.

Thanks for a useful info. You've probably saved me a lot of time spent on catching those bugs in future.
But I didn't get... You've run into "1000ms" bug with my user-model testcase, haven't you?

Owner

lefnire commented Jan 19, 2013

not with that simple test case, but I've found consecutive writes causing 1000ms bug under load. And come to think of it, I think we know exactly what's happening now. Racer -> MongoDB scaling issue. Too many writes to the database server, the next write has to wait. Racer says wait 1000ms, if that times out fail. You can (and should) increase that for production, but that's no substitute for more sane writes - aka, whole document saves vs. a ton of tiny writes. I think you're getting the error because of slower access to the db server, or fast refreshing, few system resources or something - but the bug is definitely caused on Habit when there's a traffic surge.

@lefnire lefnire referenced this issue Jan 20, 2013

Closed

Undo Button? #6

Owner

lefnire commented Jan 21, 2013

ALRIGHTY THEN! Now on to some real bugs!

@lefnire lefnire closed this Jan 21, 2013

@lefnire lefnire referenced this issue Jan 21, 2013

Closed

Timezone issue #148

Owner

lefnire commented Jan 21, 2013

Ok, we're not totally in the clear - this is 90% fixed now that a lot of model-saving is offloaded to the server for en-masse updates (see this comment above), but there are still some required client-side updates that spam .set(), and we need to figure out how to reduce that because it still locks mongohq periodically

@lefnire lefnire reopened this Jan 21, 2013

This was referenced Jan 21, 2013

Owner

lefnire commented Jan 22, 2013

So I've been working with this issue for a a week or more now, and it's verified not a Racer issue, but MongoDB. It just means "the query was super slow". I've optimized .set operations as best as I could, and I'm using MongoHQ monitoring to verify we've reduced updates & reads. It's still performing a high amount of reads & updates per second (200-300), so there's optimizations yet to be had, but less than before. Two lessons learned for optimizations: don't spam .set, but also don't update the document whole-sale if you don't have to - that's just as bad. Just be wise with .sets.

I've also setup indexes on common user queries, but the most common of all - user._id - doesn't appear to be being used. I think it's because we're subscribing to a read path "users.#{userId}" rather than using a query model.query('users').withId(userId). I tried switching over, but am hitting the issues outlined here. Anyone seen that before or have ideas? @switz or @Andrew565

Owner

lefnire commented Jan 22, 2013

for one reason or another, query.withId(id) doesn't work with racer-db-mongo (works fine with memory store), while query.where('id').equals(id) works fine. Probably a racer-db-mongo bug, meh - good enough

@lefnire lefnire closed this Jan 22, 2013

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment