Re: Issue with Promises resolving timely

[Daniel Kluss]

Yup that fixed it for me, but I could see it being a performance issue calling it so often.

node.cc

inline int Start(Isolate* isolate, IsolateData* isolate_data,

                 int argc, const char* const* argv,

                 int exec_argc, const char* const* exec_argv) {

  HandleScope handle_scope(isolate);

  Local<Context> context = Context::New(isolate);

  Context::Scope context_scope(context);

  Environment env(isolate_data, context);

  env.Start(argc, argv, exec_argc, exec_argv, v8_is_profiling);

  // Start debug agent when argv has --debug

  if (use_debug_agent) {

    const char* path = argc > 1 ? argv[1] : nullptr;

    StartDebug(&env, path, debug_wait_connect);

    if (use_inspector && !debugger_running)

      return 12;  // Signal internal error.

  }

  {

    Environment::AsyncCallbackScope callback_scope(&env);

    LoadEnvironment(&env);

  }

  env.set_trace_sync_io(trace_sync_io);

  // Enable debugger

  if (use_debug_agent)

    EnableDebug(&env);

  {

    SealHandleScope seal(isolate);

    bool more;

    do {

      v8_platform.PumpMessageLoop(isolate);

  env.isolate()->RunMicrotasks();  /*ADDED THIS RIGHT HERE*/

      more = uv_run(env.event_loop(), UV_RUN_ONCE);

      if (more == false) {

        v8_platform.PumpMessageLoop(isolate);

        EmitBeforeExit(&env);

        // Emit `beforeExit` if the loop became alive either after emitting

        // event, or after running some callbacks.

        more = uv_loop_alive(env.event_loop());

        if (uv_run(env.event_loop(), UV_RUN_NOWAIT) != 0)

          more = true;

      }

    } while (more == true);

  }

  env.set_trace_sync_io(false);

  const int exit_code = EmitExit(&env);

  RunAtExit(&env);

  WaitForInspectorDisconnect(&env);

#if defined(LEAK_SANITIZER)

  __lsan_do_leak_check();

#endif

  return exit_code;

}

On Mon, Dec 5, 2016 at 3:23 AM, Daniel Kluss <code...@gmail.com> wrote:

I figured it out, NodeJS does not check to see if any microtasks need to be run before taking a nice nap for timers, adding "isolate->RunMicrotasks();" just after resolving fixes it for me, but this a real bug.

At least when native c++ addons are calling resolve, nothing happens until RunMicrotasks() is called

I am thinking up ways to fix this, but i don't know at the moment the best place to insert RunMicrotasks(), probably just before "uv_run(env.event_loop(), UV_RUN_ONCE);" in node.cc, because that is when it takes naps

On Mon, Dec 5, 2016 at 2:31 AM, Daniel Kluss <code...@gmail.com> wrote:

When setTimeout is used promises wait for it to complete, instead of going quickly like normal

Below is the snippets involved, i can post whole thing. I think i must be doing something wrong, I don't assume a bug in node or libuv just yet.

Also, since resolve is called between "staticAfterWork" and "staticAfterWork done", why does the 'then' message of timing not print between them.

It appears the 'then' function calls get queued up for later, and the queue isn't run thru until after the timers queue if it has anything in it.

using Windows 10x64, node 7.2 x64, 

command and output

node --harmony test

1188880625 staticDoWork

1188880625 staticDoWork done

1188880625 staticAfterWork

1188880625 staticAfterWork done

test_no_timeout: 27.506ms

1188880656 staticDoWork

1188880687 staticDoWork done

1188880718 staticAfterWork

1188880718 staticAfterWork done

test_with_timeout: 3001.294ms

js code

function test_no_timeout() {

console.time('test_no_timeout');

intrinsics._promise_worker_sleep(1).then(()=>{

console.timeEnd('test_no_timeout');

setImmediate(test_with_timeout);

});

}

function test_with_timeout() {

setTimeout(()=>{}, 3000);

console.time('test_with_timeout');

intrinsics._promise_worker_sleep(1).then(()=>{

console.timeEnd('test_with_timeout');

});

}

test_no_timeout();

c++ addon

template<typename T> 

class WorkerArgsAndResolver {

public:

v8::Global<v8::Promise::Resolver> resolver;

static void staticDoWork(uv_work_t* req) {

printf("%u staticDoWork\n", GetTickCount());

static_cast<T *>(req->data)->doWork(req);

printf("%u staticDoWork done\n", GetTickCount());

}

static void staticAfterWork(uv_work_t* req, int status) {

printf("%u staticAfterWork\n", GetTickCount());

static_cast<T *>(req->data)->afterWork(req, status);

delete static_cast<T *>(req->data);

delete req;

printf("%u staticAfterWork done\n", GetTickCount());

}

WorkerArgsAndResolver(const v8::FunctionCallbackInfo<v8::Value>& info) {

v8::Isolate* isolate = v8::Isolate::GetCurrent();

v8::HandleScope scope(isolate);

auto LocalResolver = v8::Promise::Resolver::New(info.GetIsolate());

info.GetReturnValue().Set(LocalResolver->GetPromise());

resolver.Reset(isolate, LocalResolver);

}

void queue() {

uv_work_t *work = new uv_work_t();

work->data = this;

uv_queue_work(uv_default_loop(), work, staticDoWork, staticAfterWork);

}

static void create(const v8::FunctionCallbackInfo<v8::Value>& info) {

new T(info);

}

};

class SleepEx_waar: public WorkerArgsAndResolver<SleepEx_waar>{

public:

uint32_t milliseconds{ 0 };

uint32_t ret{ 0 };

void doWork(uv_work_t* req) {

auto beginTicks = GetTickCount();

Sleep(milliseconds);

auto finishTicks = GetTickCount();

ret = finishTicks - beginTicks;

}

void afterWork(uv_work_t* req, int status) {

v8::Isolate* isolate = v8::Isolate::GetCurrent();

v8::HandleScope scope(isolate);

resolver.Get(isolate)->Resolve(v8::Integer::NewFromUnsigned(isolate, ret));

}

SleepEx_waar(const v8::FunctionCallbackInfo<v8::Value>& info): WorkerArgsAndResolver(info) {

milliseconds = info.Length()>0?info[0]->Uint32Value():0;

queue();

}

};