Skip to content

Commit

Permalink
lib: don't penalize setInterval() common case
Browse files Browse the repository at this point in the history
The common case is where setInterval() is called with two arguments,
the callback and the timeout.  Specifying optional arguments in
the parameter list forces common case calls to go through an arguments
adaptor stack frame.

PR-URL: #1221
Reviewed-By: Trevor Norris <trev.norris@gmail.com>
  • Loading branch information
bnoordhuis committed Mar 20, 2015
1 parent 31da975 commit 33fea6e
Showing 1 changed file with 28 additions and 30 deletions.
58 changes: 28 additions & 30 deletions lib/timers.js
Original file line number Diff line number Diff line change
Expand Up @@ -229,52 +229,50 @@ exports.clearTimeout = function(timer) {
};


exports.setInterval = function(callback, repeat, arg1, arg2, arg3) {
exports.setInterval = function(callback, repeat) {
repeat *= 1; // coalesce to number or NaN

if (!(repeat >= 1 && repeat <= TIMEOUT_MAX)) {
repeat = 1; // schedule on next tick, follows browser behaviour
}

var args, i;
var timer = new Timeout(repeat);
var len = arguments.length - 2;
timer._onTimeout = wrapper;
timer._repeat = true;
// Initialize args once for repeated invocation of slow case below
if (len > 3) {
args = new Array(len);
for (i = 0; i < len; i++)
args[i] = arguments[i + 2];
var length = arguments.length;
var ontimeout = callback;
switch (length) {
case 0:
case 1:
case 2:
break;
case 3:
ontimeout = callback.bind(timer, arguments[2]);
break;
case 4:
ontimeout = callback.bind(timer, arguments[2], arguments[3]);
break;
case 5:
ontimeout =
callback.bind(timer, arguments[2], arguments[3], arguments[4]);
break;
default:
var args = new Array(length - 2);
for (var i = 2; i < length; i += 1)
args[i - 2] = arguments[i];
ontimeout = callback.apply.bind(callback, timer, args);
break;
}
timer._onTimeout = wrapper;
timer._repeat = ontimeout;

if (process.domain) timer.domain = process.domain;
exports.active(timer);

return timer;

function wrapper() {
switch (len) {
// fast cases
case 0:
callback.call(this);
break;
case 1:
callback.call(this, arg1);
break;
case 2:
callback.call(this, arg1, arg2);
break;
case 3:
callback.call(this, arg1, arg2, arg3);
break;
// slow case
default:
callback.apply(this, args);
break;
}
timer._repeat.call(this);
// If callback called clearInterval().
if (timer._repeat === false) return;
if (timer._repeat === null) return;
// If timer is unref'd (or was - it's permanently removed from the list.)
if (this._handle) {
this._handle.start(repeat, 0);
Expand Down

14 comments on commit 33fea6e

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@bnoordhuis this patch gives me an error when #1152 is applied on it:

Jeremiahs-MacBook-Pro:io.js Jeremiah$ ./iojs_g test/parallel/test-timers-unref.js


#
# Fatal error in ../deps/v8/src/api.h, line 386
# CHECK(allow_empty_handle || that != __null) failed
#

==== C stack trace ===============================

 1: ??
 2: ??
 3: ??
 4: ??
 5: ??
 6: ??
 7: ??
 8: ??
 9: ??
10: ??
11: ??
Illegal instruction: 4

@bnoordhuis
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What does the backtrace look like in gdb or lldb?

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

./configure --debug --gdb Didn't change anything, I'll try to get gdb/lldb configured properly tomorrow.

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Using https://github.com/thlorenz/lldb-jbt

Jeremiahs-MacBook-Pro:io.js Jeremiah$ lldb -- ./iojs_g --perf-basic-prof test/parallel/test-timers-unref.js
(lldb) target create "./iojs_g"
Current executable set to './iojs_g' (x86_64).
(lldb) settings set -- target.run-args  "--perf-basic-prof" "test/parallel/test-timers-unref.js"
(lldb) run
Process 55202 launched: './iojs_g' (x86_64)


#
# Fatal error in ../../deps/v8/src/api.h, line 386
# CHECK(allow_empty_handle || that != __null) failed
#

==== C stack trace ===============================

 1: ??
(...)
11: ??
Process 55202 stopped
* thread #1: tid = 0x4d4be, 0x0000000100a4c661 iojs_g`v8::base::OS::Abort() + 17 at platform-posix.cc:212, queue = 'com.apple.main-thread', stop reason = EXC_BAD_INSTRUCTION (code=EXC_I386_INVOP, subcode=0x0)
    frame #0: 0x0000000100a4c661 iojs_g`v8::base::OS::Abort() + 17 at platform-posix.cc:212
   209  
   210  void OS::Abort() {
   211    if (g_hard_abort) {
-> 212      V8_IMMEDIATE_CRASH();
   213    }
   214    // Redirect to std abort to signal abnormal program termination.
   215    abort();
(lldb) quit

Still no stack frames, but error seems expanded?

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, using lldb-jbt properly (i think) now:

* thread #1: tid = 0x5149f, 0x00007fff87721286 libsystem_kernel.dylib`__pthread_kill + 10, queue = 'com.apple.main-thread', stop reason = signal SIGABRT
    frame #0: 0x00007fff87721286 libsystem_kernel.dylib`__pthread_kill + 10
libsystem_kernel.dylib`__pthread_kill + 10:
-> 0x7fff87721286:  jae    0x7fff87721290            ; __pthread_kill + 20
   0x7fff87721288:  movq   %rax, %rdi
   0x7fff8772128b:  jmp    0x7fff8771cc53            ; cerror_nocancel
   0x7fff87721290:  retq 

EDIT: Also got bt for this: EDIT2: using jbt:

(lldb) jbt
* thread: #1: tid = 0x53eb6, frame #0: 0x00007fff87721286 libsystem_kernel.dylib`__pthread_kill + 10
 * frame #0: 0x00007fff87721286 libsystem_kernel.dylib`__pthread_kill + 10
   frame #1: 0x00007fff915f942f libsystem_pthread.dylib`pthread_kill + 90
   frame #2: 0x00007fff94c8eb53 libsystem_c.dylib`abort + 129
   frame #3: 0x00007fff94c56c39 libsystem_c.dylib`__assert_rtn + 321
   frame #4: 0x00000001009cba4e iojs_g`node::AsyncWrap::MakeCallback(this=0x0000000101e0c050, index=0, argc=0, argv=0x0000000000000000) + 142 at async-wrap-inl.h:85
   frame #5: 0x00000001009cb99d iojs_g`node::TimerWrap::OnTimeout(handle=0x0000000101e0c090) + 125 at timer_wrap.cc:119
   frame #6: 0x0000000100a3ebd5 iojs_g`uv__run_timers(loop=0x0000000100fe4478) + 149 at timer.c:165
   frame #7: 0x0000000100a2aa6b iojs_g`uv_run(loop=0x0000000100fe4478, mode=UV_RUN_ONCE) + 123 at core.c:315
   frame #8: 0x000000010097b044 iojs_g`node::StartNodeInstance(arg=0x00007fff5fbff780) + 436 at node.cc:3837
   frame #9: 0x000000010097ae38 iojs_g`node::Start(argc=2, argv=0x0000000101e09110) + 280 at node.cc:3897
   frame #10: 0x00000001009a79f2 iojs_g`main(argc=3, argv=0x00007fff5fbff828) + 34 at node_main.cc:44
   frame #11: 0x00000001000010f4 iojs_g`start + 52

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmmm, something else? (by running the above again..)

* thread #1: tid = 0x5260f, 0x0000000100223b2c iojs_g`v8::internal::Isolate::thread_manager(this=0xffffffffffffffff) + 12 at isolate.h:940, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x6507)
    frame #0: 0x0000000100223b2c iojs_g`v8::internal::Isolate::thread_manager(this=0xffffffffffffffff) + 12 at isolate.h:940
   937  
   938    EternalHandles* eternal_handles() { return eternal_handles_; }
   939  
-> 940    ThreadManager* thread_manager() { return thread_manager_; }
   941  
   942    StringTracker* string_tracker() { return string_tracker_; }
   943  

(this time with bt after) EDIT: with jbt:

(lldb) jbt
* thread: #1: tid = 0x54381, frame #0: 0x0000000100223b2c iojs_g`v8::internal::Isolate::thread_manager(this=0x0001030400100000) + 12 at isolate.h:940
 * frame #0: 0x0000000100223b2c iojs_g`v8::internal::Isolate::thread_manager(this=0x0001030400100000) + 12 at isolate.h:940
   frame #1: 0x00000001001fff20 iojs_g`v8::HandleScope::Initialize(this=0x00007fff5fbff5b0, isolate=0x0001030400100000) + 64 at api.cc:463
   frame #2: 0x00000001001ffecd iojs_g`v8::HandleScope::HandleScope(this=0x00007fff5fbff5b0, isolate=0x0001030400100000) + 29 at api.cc:453
   frame #3: 0x00000001001ff44d iojs_g`v8::HandleScope::HandleScope(this=0x00007fff5fbff5b0, isolate=0x0001030400100000) + 29 at api.cc:454
   frame #4: 0x00000001009cb959 iojs_g`node::TimerWrap::OnTimeout(handle=0x0000000102d00ae0) + 57 at timer_wrap.cc:117
   frame #5: 0x0000000100a3ebd5 iojs_g`uv__run_timers(loop=0x0000000100fe4478) + 149 at timer.c:165
   frame #6: 0x0000000100a2ab00 iojs_g`uv_run(loop=0x0000000100fe4478, mode=UV_RUN_ONCE) + 272 at core.c:338
   frame #7: 0x000000010097b044 iojs_g`node::StartNodeInstance(arg=0x00007fff5fbff780) + 436 at node.cc:3837
   frame #8: 0x000000010097ae38 iojs_g`node::Start(argc=2, argv=0x0000000101e09110) + 280 at node.cc:3897
   frame #9: 0x00000001009a79f2 iojs_g`main(argc=3, argv=0x00007fff5fbff828) + 34 at node_main.cc:44
   frame #10: 0x00000001000010f4 iojs_g`start + 52

@bnoordhuis
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

frame #4: 0x00000001009cba4e iojs_g`node::AsyncWrap::MakeCallback(this=0x0000000101e0c050, index=0, argc=0, argv=0x0000000000000000) + 142 at async-wrap-inl.h:85

That assert implies that the timer callback is not a function.

frame #0: 0x0000000100223b2c iojs_g`v8::internal::Isolate::thread_manager(this=0x0001030400100000) + 12 at isolate.h:940

If that segfaults, it suggests a wild pointer.

I speculate we're looking at memory corruption due to bad lifecycle management of unref'd timers. Possible causes: deleting the TimerWrap before the uv_timer_t handle is closed, closing the uv_timer_t when the persistent handle is not dead yet, etc.

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A third?

* thread #1: tid = 0x5667d, 0x0000000100a3e515 iojs_g`heap_insert(heap=0x0000000100fe4730, newnode=0x0000000102e00888, less_than=0x0000000100a3e590) + 277 at heap-inl.h:140, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=1, address=0x8)
    frame #0: 0x0000000100a3e515 iojs_g`heap_insert(heap=0x0000000100fe4730, newnode=0x0000000102e00888, less_than=0x0000000100a3e590) + 277 at heap-inl.h:140
   137  
   138    /* Insert the new node. */
   139    newnode->parent = *parent;
-> 140    *child = newnode;
   141    heap->nelts += 1;
   142  
   143    /* Walk up the tree and check at each node if the heap property holds.
(lldb) jbt
* thread: #1: tid = 0x5667d, frame #0: 0x0000000100a3e515 iojs_g`heap_insert(heap=0x0000000100fe4730, newnode=0x0000000102e00888, less_than=0x0000000100a3e590) + 277 at heap-inl.h:140
 * frame #0: 0x0000000100a3e515 iojs_g`heap_insert(heap=0x0000000100fe4730, newnode=0x0000000102e00888, less_than=0x0000000100a3e590) + 277 at heap-inl.h:140
   frame #1: 0x0000000100a3e204 iojs_g`uv_timer_start(handle=0x0000000102e00820, cb=0x00000001009cb920, timeout=100, repeat=0) + 260 at timer.c:84
   frame #2: 0x00000001009cb635 iojs_g`node::TimerWrap::Start(args=0x00007fff5fbfea00) + 149 at timer_wrap.cc:78
   frame #3: 0x000000010024d0fc iojs_g`v8::internal::FunctionCallbackArguments::Call(this=0x00007fff5fbfeb00, f=0x00000001009cb5a0)(v8::FunctionCallbackInfo<v8::Value> const&)) + 124 at arguments.cc:33
   frame #4: 0x0000000100297ee4 iojs_g`v8::internal::Object* v8::internal::HandleApiCallHelper<false>(args=BuiltinArguments<1> at 0x00007fff5fbfec18, isolate=0x0000000102007600)::BuiltinArguments<(v8::internal::BuiltinExtraArguments)1>, v8::internal::Isolate*) + 1348 at builtins.cc:1139
   frame #5: 0x0000000100297995 iojs_g`v8::internal::Builtin_Impl_HandleApiCall(args=v8::internal::<anonymous namespace>::HandleApiCallArgumentsType at 0x00007fff5fbfec60, isolate=0x0000000102007600)::BuiltinArguments<(v8::internal::BuiltinExtraArguments)1>, v8::internal::Isolate*) + 53 at builtins.cc:1156
   frame #6: 0x0000000100291800 iojs_g`v8::internal::Builtin_HandleApiCall(args_length=4, args_object=0x00007fff5fbfed10, isolate=0x0000000102007600) + 80 at builtins.cc:1155
   frame #7: 0x0000128695d060bb Stub:CEntryStub
   frame #8: 0x0000128695de49c8 ~insert timers.js:28
   frame #9: 0x0000128695de45b3 ~exports.active timers.js:157
   frame #10: 0x0000128695df024a ~wrapper timers.js:272
   frame #11: 0x0000128695df23a8 listOnTimeout timers.js:53
   frame #12: 0x0000128695d1f160 Builtin:JSEntryTrampoline
   frame #13: 0x0000128695d1dff1 Stub:JSEntryStub
   frame #14: 0x0000000100474a11 iojs_g`v8::internal::Invoke(is_construct=false, function=Handle<v8::internal::JSFunction> at 0x00007fff5fbff020, receiver=Handle<v8::internal::Object> at 0x00007fff5fbff018, argc=0, args=0x0000000000000000) + 705 at execution.cc:103
   frame #15: 0x0000000100474413 iojs_g`v8::internal::Execution::Call(isolate=0x0000000102007600, callable=Handle<v8::internal::Object> at 0x00007fff5fbff0c0, receiver=Handle<v8::internal::Object> at 0x00007fff5fbff0b8, argc=0, argv=0x0000000000000000, convert_receiver=true) + 691 at execution.cc:153
   frame #16: 0x0000000100215642 iojs_g`v8::Function::Call(this=0x000000010204b210, recv=(val_ = v8::Value * = 0x0000000104028820), argc=0, argv=0x0000000000000000) + 466 at api.cc:4183
   frame #17: 0x0000000100959ee8 iojs_g`node::AsyncWrap::MakeCallback(this=0x0000000102d00240, cb=(val_ = v8::Function * = 0x000000010204b210), argc=0, argv=0x0000000000000000) + 1928 at async-wrap.cc:131
   frame #18: 0x00000001009cba7c iojs_g`node::AsyncWrap::MakeCallback(this=0x0000000102d00240, index=0, argc=0, argv=0x0000000000000000) + 188 at async-wrap-inl.h:86
   frame #19: 0x00000001009cb99d iojs_g`node::TimerWrap::OnTimeout(handle=0x0000000102d00280) + 125 at timer_wrap.cc:119
   frame #20: 0x0000000100a3ebd5 iojs_g`uv__run_timers(loop=0x0000000100fe4478) + 149 at timer.c:165
   frame #21: 0x0000000100a2ab00 iojs_g`uv_run(loop=0x0000000100fe4478, mode=UV_RUN_ONCE) + 272 at core.c:338
   frame #22: 0x000000010097b044 iojs_g`node::StartNodeInstance(arg=0x00007fff5fbff780) + 436 at node.cc:3837
   frame #23: 0x000000010097ae38 iojs_g`node::Start(argc=2, argv=0x0000000101e09110) + 280 at node.cc:3897
   frame #24: 0x00000001009a79f2 iojs_g`main(argc=3, argv=0x00007fff5fbff828) + 34 at node_main.cc:44
   frame #25: 0x00000001000010f4 iojs_g`start + 52

@bnoordhuis
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, so that's almost certainly some kind of memory corruption. :-)

This commit can't have introduced it but maybe it exposes it.

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So this exposes mem corruption in #1152's patch then?

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

(i.e. this stack if from this commit + those patches)

@bnoordhuis
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If I had to guess, I'd say the call to this.owner.close() in #1152 has something to do with it.

@Fishrock123
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right, I suspected as much.
cc @trevnorris

@trevnorris
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reason for calling close() is to make sure the destructor is called. Ah suck, though now thinking about it if there are multiple JS timers linked to the same C++ TimerWrap class then all hell could break loose. So .close() should only be run if the calling timer is the last timer attached to that class instance.

Ref: 0d05123

Please sign in to comment.