src: trace threadpool event

[theanarkh]

trace threadpool events, such as APIs of Blob, zlib, crypto and node_api.

• make -j4 test (UNIX), or vcbuild test (Windows) passes
• tests and/or benchmarks are included
• documentation is changed or added
• commit message follows commit guidelines

[theanarkh]

@legendecas @RaisinTen Hi, can we just trace the total time of work. the code is as follows.

void ThreadPoolWork::ScheduleWork() {
  env_->IncreaseWaitingRequestCounter();

  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(...);

  int status = uv_queue_work(
      env_->event_loop(),
      &work_req_,
      [](uv_work_t* req) {
        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
        self->DoThreadPoolWork();
      },
      [](uv_work_t* req, int status) {
        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
        self->env_->DecreaseWaitingRequestCounter();

        TRACE_EVENT_NESTABLE_ASYNC_END1(...);

        self->AfterThreadPoolWork(status);
      });
  CHECK_EQ(status, 0);
}

Or trace all the time by two different event type.

void ThreadPoolWork::ScheduleWork() {
  env_->IncreaseWaitingRequestCounter();

  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(...);

  int status = uv_queue_work(
      env_->event_loop(),
      &work_req_,
      [](uv_work_t* req) {
        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
        TRACE_EVENT_BEGIN(...);
        self->DoThreadPoolWork();
        TRACE_EVENT_END(...);
      },
      [](uv_work_t* req, int status) {
        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
        self->env_->DecreaseWaitingRequestCounter();

        TRACE_EVENT_NESTABLE_ASYNC_END1(...);

        self->AfterThreadPoolWork(status);
      });
  CHECK_EQ(status, 0);
}

[legendecas]

I'd still find that tracing the synchronous event is important. So the latter alternative is LGTM.

[theanarkh]

It seems we can not use TRACE_EVENT_BEGIN0 and TRACE_EVENT_END0 in another thread, i will take a look later.
https://github.com/nodejs/node/actions/runs/3054446637/jobs/4926355622.

[theanarkh]

@legendecas Hi, it seems the TRACE_EVENT_xx is not thread-safe, so i record the time of synchronous API call in args field of async event. what do you think ?

[legendecas]

@theanarkh The macros are declared to be thread-safe. If there is any problem related to thread safety, it should be fixed.

I'd find the problem here is related to the incomplete shutdown -- e.g. the global state of the tracing controller is not reset after the platform is shut down https://github.com/nodejs/node/blob/main/src/tracing/trace_event.cc#L8. This global state is used in the macro expansion: https://github.com/nodejs/node/blob/main/src/tracing/trace_event.h#L474. We should properly shut down the platform with the tracing global state.

[theanarkh]

Do you mean this test case https://github.com/nodejs/node/actions/runs/3054446637/jobs/4926355622 ? I remember when i change common.platformTimeout(10) to common.platformTimeout(100), the test exits normally🤔.

[legendecas]

@theanarkh yeah, IIUC that test case is exactly testing a premature exit while the async work is still in progress.

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/47605/

[nodejs-github-bot]

Landed in 8fb282e