src: trace threadpool event by theanarkh · Pull Request #44458 · nodejs/node · GitHub

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

@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);
}

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

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.

@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 ?

@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.

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🤔.

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

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

Landed in 8fb282e

When the process exits, there may be tasks in the thread pool that need to access data in the platform, such as trace agent. So make sure the thread pool exits first. see #44458 PR-URL: #45226 Refs: #44458 Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Santiago Gimeno <santiago.gimeno@gmail.com> Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com>

PR-URL: #44458 Reviewed-By: Chengzhong Wu <legendecas@gmail.com>

When the process exits, there may be tasks in the thread pool that need to access data in the platform, such as trace agent. So make sure the thread pool exits first. see #44458 PR-URL: #45226 Refs: #44458 Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Santiago Gimeno <santiago.gimeno@gmail.com> Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com>

PR-URL: #44458 Reviewed-By: Chengzhong Wu <legendecas@gmail.com>

PR-URL: #45266 Refs: #45092 Refs: #44458 Reviewed-By: Darshan Sen <raisinten@gmail.com> Reviewed-By: Chengzhong Wu <legendecas@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

When the process exits, there may be tasks in the thread pool that need to access data in the platform, such as trace agent. So make sure the thread pool exits first. see #44458 PR-URL: #45226 Refs: #44458 Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Santiago Gimeno <santiago.gimeno@gmail.com> Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com>

PR-URL: #44458 Reviewed-By: Chengzhong Wu <legendecas@gmail.com>

PR-URL: #45266 Refs: #45092 Refs: #44458 Reviewed-By: Darshan Sen <raisinten@gmail.com> Reviewed-By: Chengzhong Wu <legendecas@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

When the process exits, there may be tasks in the thread pool that need to access data in the platform, such as trace agent. So make sure the thread pool exits first. see #44458 PR-URL: #45226 Refs: #44458 Reviewed-By: Ben Noordhuis <info@bnoordhuis.nl> Reviewed-By: Santiago Gimeno <santiago.gimeno@gmail.com> Reviewed-By: Juan José Arboleda <soyjuanarbol@gmail.com>

PR-URL: #44458 Reviewed-By: Chengzhong Wu <legendecas@gmail.com>

PR-URL: #45266 Refs: #45092 Refs: #44458 Reviewed-By: Darshan Sen <raisinten@gmail.com> Reviewed-By: Chengzhong Wu <legendecas@gmail.com> Reviewed-By: James M Snell <jasnell@gmail.com>

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. needs-ci PRs that need a full CI run. labels Aug 30, 2022

theanarkh force-pushed the trace_threadpoolwork_event branch from 6f35dbf to 245ef10 Compare August 30, 2022 16:35

legendecas reviewed Aug 30, 2022

View reviewed changes

Comment thread src/threadpoolwork-inl.h Outdated

theanarkh force-pushed the trace_threadpoolwork_event branch 2 times, most recently from b87e591 to 39bd5b5 Compare August 30, 2022 17:44

VoltrexKeyva reviewed Aug 31, 2022

View reviewed changes

Comment thread src/node_internals.h Outdated

theanarkh force-pushed the trace_threadpoolwork_event branch from 39bd5b5 to 39f400b Compare August 31, 2022 02:26

legendecas reviewed Aug 31, 2022

View reviewed changes

Comment thread src/node_internals.h Outdated

theanarkh force-pushed the trace_threadpoolwork_event branch from 39f400b to ef94baa Compare August 31, 2022 02:40

legendecas reviewed Aug 31, 2022

View reviewed changes

Comment thread src/threadpoolwork-inl.h Outdated

Comment thread doc/api/tracing.md Outdated

Comment thread doc/api/tracing.md Outdated

theanarkh force-pushed the trace_threadpoolwork_event branch 2 times, most recently from 40c49ab to 672d9ad Compare August 31, 2022 13:24

addaleax reviewed Aug 31, 2022

View reviewed changes

Comment thread src/node_internals.h Outdated

theanarkh force-pushed the trace_threadpoolwork_event branch 2 times, most recently from e077266 to 24d32ce Compare September 1, 2022 06:28

RaisinTen reviewed Sep 2, 2022

View reviewed changes

Comment thread src/threadpoolwork-inl.h Outdated

Comment thread src/threadpoolwork-inl.h Outdated

Comment thread src/threadpoolwork-inl.h Outdated

Comment thread src/threadpoolwork-inl.h Outdated

theanarkh force-pushed the trace_threadpoolwork_event branch 2 times, most recently from 1703fd4 to 05cbb9c Compare September 14, 2022 16:26

theanarkh force-pushed the trace_threadpoolwork_event branch 3 times, most recently from a8b5f8f to b1128a1 Compare October 26, 2022 00:38

theanarkh force-pushed the trace_threadpoolwork_event branch from b1128a1 to 1f402fc Compare October 26, 2022 01:30

github-actions Bot mentioned this pull request Nov 1, 2022

CI Reliability 2022-11-01 nodejs/reliability#417

Open

17 tasks

theanarkh added the commit-queue Add this label to land a pull request using GitHub Actions. label Nov 1, 2022

nodejs-github-bot removed the commit-queue Add this label to land a pull request using GitHub Actions. label Nov 1, 2022

nodejs-github-bot merged commit 8fb282e into nodejs:main Nov 1, 2022

RafaelGSS pushed a commit that referenced this pull request Nov 1, 2022

src: trace threadpool event

7ccabbf

PR-URL: #44458 Reviewed-By: Chengzhong Wu <legendecas@gmail.com>

theanarkh mentioned this pull request Nov 1, 2022

trace_events: add new categories #45266

Merged

4 tasks

RafaelGSS mentioned this pull request Nov 1, 2022

v19.1.0 proposal #45269

Merged

This was referenced Nov 2, 2022

CI Reliability 2022-11-02 nodejs/reliability#418

Open

CI Reliability 2022-11-05 nodejs/reliability#419

Open

RafaelGSS pushed a commit that referenced this pull request Nov 10, 2022

src: trace threadpool event

3e46ebd

PR-URL: #44458 Reviewed-By: Chengzhong Wu <legendecas@gmail.com>

danielleadams mentioned this pull request Dec 30, 2022

v18.13.0 release proposal #46025

Merged

danielleadams pushed a commit that referenced this pull request Dec 30, 2022

src: trace threadpool event

4ee33a4

PR-URL: #44458 Reviewed-By: Chengzhong Wu <legendecas@gmail.com>

danielleadams pushed a commit that referenced this pull request Jan 3, 2023

src: trace threadpool event

4634aa9

PR-URL: #44458 Reviewed-By: Chengzhong Wu <legendecas@gmail.com>

src: trace threadpool event by theanarkh · Pull Request #44458 · nodejs/node · GitHub

Uh oh!

Uh oh!

src: trace threadpool event - #44458

src: trace threadpool event#44458nodejs-github-bot merged 1 commit intonodejs:mainnodejs/node:mainfrom theanarkh:trace_threadpoolwork_eventtheanarkh/node:trace_threadpoolwork_eventCopy head branch name to clipboard

Conversation

theanarkh commented Aug 30, 2022

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

theanarkh commented Sep 9, 2022

Uh oh!

legendecas commented Sep 14, 2022

Uh oh!

theanarkh commented Sep 14, 2022

Uh oh!

theanarkh commented Oct 26, 2022

Uh oh!

legendecas commented Oct 26, 2022

Uh oh!

theanarkh commented Oct 26, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

legendecas commented Oct 26, 2022

Uh oh!

nodejs-github-bot commented Oct 31, 2022

Uh oh!

nodejs-github-bot commented Nov 1, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

7 participants

src: trace threadpool event#44458
nodejs-github-bot merged 1 commit into
nodejs:mainfrom
theanarkh:trace_threadpoolwork_event

theanarkh commented Oct 26, 2022 •
edited
Loading