src: add loop idle time in diagnostic report #35940

gireeshpunathil · 2020-11-03T07:31:14Z

Add libuv's cumulative idle time in the diagnostic report.
Modify the structure of libuv section to cater to this change

Refs: #34938

before

  "libuv": [
    {
      "type": "async",
      "is_active": true,
      "is_referenced": false,
      "address": "0x0000000105a0bd70"
    }
  ]

after

  "libuv": {
    "loop_idle_time": 22644.8,
    "handles": [
      {
      "type": "async",
      "is_active": true,
      "is_referenced": false,
      "address": "0x0000000105a0bd70"
      }
    ]
  }

Checklist

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

richardlau · 2020-11-03T10:56:14Z

Add libuv's cumulative idle time in the diagnostic report.
Modify the structure of libuv section to cater to this change

Refs: #34938

before

  "libuv": [
    {
      "type": "async",
      "is_active": true,
      "is_referenced": false,
      "address": "0x0000000105a0bd70"
    }
  ]

after

  "libuv": {
    "loop_idle_time": 22644.8,
    "handles": [
      {
      "type": "async",
      "is_active": true,
      "is_referenced": false,
      "address": "0x0000000105a0bd70"
      }
    ]
  }

Is this structural change (as opposed to just a new field) the sort of thing that should bump reportVersion?
cc @boneskull

gireeshpunathil · 2020-11-03T11:05:56Z

@richardlau - it is a new field addition, but that led to a structural change too. Original structure libuv was an array as it contained homogeneous entries. But now with the idle time in it, it is no more uniform, so I converted it into an object. Happy to move it either side, upon review comments:

retain the libuv 's original structure and add the field elsewhere
modify the structure and bump the version

cjihrig · 2020-11-03T13:56:08Z

I think the report version should be bumped. Can you also update the example report in the documentation.

gireeshpunathil · 2020-11-03T16:57:18Z

all - I have bumped the report version to 3, and reflected the change in the doc too. PTAL!

addaleax · 2020-11-03T21:40:40Z

Why do we not add this to the loop entry in the handles list? That would a) be more consistent than this PR, because that’s where information about the loop currently goes and b) prevent a breaking change to the format that we can avoid that way.

gireeshpunathil · 2020-11-04T04:44:51Z

@addaleax - to confirm my understanding, are you proposing this style?

  "libuv": [
    {
      "type": "async",
      "is_active": true,
      "is_referenced": false,
      "address": "0x0000000105a0bd70"
    },
    {
      "loop_idle_time": 22644.8
    }
  ]

gireeshpunathil · 2020-11-04T04:47:35Z

or I guess here, as an additional key-value pair:

{
  "type": "loop",
  "is_active": true,
  "address": "0x000055fc7b2cb180",
  "loop_idle_time": 22644.8
}

?

addaleax · 2020-11-04T09:16:59Z

@gireeshpunathil Yes, the latter, for the loop entry in the handles list.

gireeshpunathil · 2020-11-04T10:03:13Z

@addaleax - done, ptal!

src/node_report.cc

richardlau

LGTM.

Maybe also add a validator for loop to the uv handles test to assert the new field is present and a number?

node/test/report/test-report-uv-handles.js

Lines 119 to 171 in 9dbde1d

    
           // Functions are named to aid debugging when they are not called. 
        
           const validators = { 
        
             fs_event: common.mustCall(function fs_event_validator(handle) { 
        
               if (!child_data.skip_fs_watch) { 
        
                 assert.strictEqual(handle.filename, expected_filename); 
        
                 assert(handle.is_referenced); 
        
               } 
        
             }), 
        
             fs_poll: common.mustCall(function fs_poll_validator(handle) { 
        
               assert.strictEqual(handle.filename, expected_filename); 
        
               assert(handle.is_referenced); 
        
             }), 
        
             pipe: common.mustCallAtLeast(function pipe_validator(handle) { 
        
               assert(handle.is_referenced); 
        
             }), 
        
             process: common.mustCall(function process_validator(handle) { 
        
               assert.strictEqual(handle.pid, child_data.pid); 
        
               assert(handle.is_referenced); 
        
             }), 
        
             tcp: common.mustCall(function tcp_validator(handle) { 
        
               // TCP handles. The report should contain three sockets: 
        
               // 1. The server's listening socket. 
        
               // 2. The inbound socket making the request. 
        
               // 3. The outbound socket sending the response. 
        
               const port = child_data.tcp_address.port; 
        
               if (handle.localEndpoint.port === port) { 
        
                 if (handle.remoteEndpoint === null) { 
        
                   found_tcp.push('listening'); 
        
                 } else { 
        
                   found_tcp.push('inbound'); 
        
                 } 
        
               } else if (handle.remoteEndpoint.port === port) { 
        
                 found_tcp.push('outbound'); 
        
               } 
        
               assert(handle.is_referenced); 
        
             }, 3), 
        
             timer: common.mustCallAtLeast(function timer_validator(handle) { 
        
               assert(!handle.is_referenced); 
        
               assert.strictEqual(handle.repeat, 0); 
        
             }), 
        
             udp: common.mustCall(function udp_validator(handle) { 
        
               if (handle.remoteEndpoint === null) { 
        
                 assert.strictEqual(handle.localEndpoint.port, 
        
                                    child_data.udp_address.port); 
        
                 found_udp.push('unconnected'); 
        
               } else { 
        
                 assert.strictEqual(handle.remoteEndpoint.port, 
        
                                    child_data.udp_address.port); 
        
                 found_udp.push('connected'); 
        
               } 
        
               assert(handle.is_referenced); 
        
             }, 2), 
        
           };

Trott

LGTM but I think doc/api/report.md still needs the relevant example updated to include this? (and the missing semicolon added to the test per linter)

nodejs-github-bot · 2020-11-10T13:15:17Z

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

trevnorris · 2020-11-11T00:32:43Z

I'm just curious. Why add it as loopIdleTimeSeconds instead of as it comes in high precision milliseconds?

addaleax · 2020-11-11T00:35:59Z

@trevnorris What would you suggest instead? Seconds were suggested by me because they match other existing fields in the diagnostic output, so we’re being a bit consistent here instead of using random units everywhere.

trevnorris · 2020-11-11T00:41:51Z

@addaleax That's fine. I just noticed the field firesInMsFromNow in the libuv array for type: 'timer' and thought of following the timing of the closest field. But I have no strong feelings either way.

nodejs-github-bot · 2020-11-11T22:55:47Z

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

gireeshpunathil · 2020-11-12T14:29:07Z

uv_metrics_idle_time is defined in uv.h and that is available through inclusion of env-inl.h. Adding node_perf.h is not required, plus it causes compilation failure in darwin, so I removed it.

@richardlau @cjihrig @addaleax @Trott - PTAL!

cjihrig

LGTM with one small question.

cjihrig · 2020-11-12T14:42:18Z

src/node_report.cc

+
+    // Report Event loop idle time
+    uint64_t idle_time = uv_metrics_idle_time(env->event_loop());
+    writer.json_keyvalue("loopIdleTimeSeconds", 1.0 * idle_time / 1e9);


Is idle_time in nanoseconds? I thought @trevnorris said it was milliseconds in #35940 (comment).

The libuv code uses uv_hrtime() without any additional scaling, so, yes, nanoseconds.

node/src/node_perf.cc

Lines 446 to 447 in 589b2a1

uint64_t idle_time = uv_metrics_idle_time(env->event_loop());

args.GetReturnValue().Set(1.0 * idle_time / 1e6);

this may make it very clear - the nanoseconds that comes is converted to millis if accessed through API.

That makes sense. I was just confused by #35940 (comment). Thanks Anna and Gireesh.

nodejs-github-bot · 2020-11-12T14:44:54Z

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

gireeshpunathil · 2020-11-13T03:03:53Z

https://ci.nodejs.org/job/node-test-binary-arm-12+/RUN_SUBSET=3,label=pi3-docker/8251/console

the failure in arm is #36090 , which is fixed now.

nodejs-github-bot · 2020-11-13T03:15:44Z

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

Add libuv's cumulative idle time in the diagnostic report. Add the data under the libuv's loop section Refs: nodejs#34938 PR-URL: nodejs#35940 Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Rich Trott <[email protected]> Reviewed-By: Richard Lau <[email protected]>

gireeshpunathil · 2020-11-13T06:28:49Z

landed in 74bd866

Add libuv's cumulative idle time in the diagnostic report. Add the data under the libuv's loop section Refs: #34938 PR-URL: #35940 Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Rich Trott <[email protected]> Reviewed-By: Richard Lau <[email protected]>

Notable changes: dns: * (SEMVER-MINOR) add a cancel() method to the promise Resolver (Szymon Marczak) #33099 events: * (SEMVER-MINOR) add max listener warning for EventTarget (James M Snell) #36001 http: * (SEMVER-MINOR) add support for abortsignal to http.request (Benjamin Gruenbaum) #36048 http2: * (SEMVER-MINOR) allow setting the local window size of a session (Yongsheng Zhang) #35978 lib: * (SEMVER-MINOR) add throws option to fs.f/l/statSync (Andrew Casey) #33716 path: * (SEMVER-MINOR) add `path/posix` and `path/win32` alias modules (ExE Boss) #34962 readline: * (SEMVER-MINOR) add getPrompt to get the current prompt (Mattias Runge-Broberg) #33675 src: * (SEMVER-MINOR) add loop idle time in diagnostic report (Gireesh Punathil) #35940 util: * (SEMVER-MINOR) add `util/types` alias module (ExE Boss) #34055 PR-URL: TODO

Notable changes: dns: * (SEMVER-MINOR) add a cancel() method to the promise Resolver (Szymon Marczak) #33099 events: * (SEMVER-MINOR) add max listener warning for EventTarget (James M Snell) #36001 http: * (SEMVER-MINOR) add support for abortsignal to http.request (Benjamin Gruenbaum) #36048 http2: * (SEMVER-MINOR) allow setting the local window size of a session (Yongsheng Zhang) #35978 lib: * (SEMVER-MINOR) add throws option to fs.f/l/statSync (Andrew Casey) #33716 path: * (SEMVER-MINOR) add `path/posix` and `path/win32` alias modules (ExE Boss) #34962 readline: * (SEMVER-MINOR) add getPrompt to get the current prompt (Mattias Runge-Broberg) #33675 src: * (SEMVER-MINOR) add loop idle time in diagnostic report (Gireesh Punathil) #35940 util: * (SEMVER-MINOR) add `util/types` alias module (ExE Boss) #34055 PR-URL: #36232

Add libuv's cumulative idle time in the diagnostic report. Add the data under the libuv's loop section Refs: #34938 PR-URL: #35940 Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Rich Trott <[email protected]> Reviewed-By: Richard Lau <[email protected]>

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. report Issues and PRs related to process.report. labels Nov 3, 2020

gireeshpunathil force-pushed the report-elu branch from 78238da to 516ec3d Compare November 4, 2020 10:02

addaleax reviewed Nov 4, 2020

View reviewed changes

src/node_report.cc Outdated Show resolved Hide resolved

addaleax approved these changes Nov 4, 2020

View reviewed changes

richardlau approved these changes Nov 4, 2020

View reviewed changes

Trott approved these changes Nov 4, 2020

View reviewed changes

Trott added the semver-minor PRs that contain new features and should be released in the next minor version. label Nov 4, 2020

cjihrig approved these changes Nov 4, 2020

View reviewed changes

Trott added request-ci Add this label to start a Jenkins CI on a PR. and removed request-ci Add this label to start a Jenkins CI on a PR. labels Nov 8, 2020

gireeshpunathil added the request-ci Add this label to start a Jenkins CI on a PR. label Nov 10, 2020

github-actions bot removed the request-ci Add this label to start a Jenkins CI on a PR. label Nov 10, 2020

This comment has been minimized.

Sign in to view

gireeshpunathil added the request-ci Add this label to start a Jenkins CI on a PR. label Nov 12, 2020

addaleax approved these changes Nov 12, 2020

View reviewed changes

cjihrig reviewed Nov 12, 2020

View reviewed changes

richardlau approved these changes Nov 12, 2020

View reviewed changes

github-actions bot removed the request-ci Add this label to start a Jenkins CI on a PR. label Nov 12, 2020

gireeshpunathil added the request-ci Add this label to start a Jenkins CI on a PR. label Nov 13, 2020

github-actions bot removed the request-ci Add this label to start a Jenkins CI on a PR. label Nov 13, 2020

gireeshpunathil force-pushed the report-elu branch from b5ee125 to 74bd866 Compare November 13, 2020 06:27

gireeshpunathil merged commit 74bd866 into nodejs:master Nov 13, 2020

codebytere mentioned this pull request Nov 22, 2020

v15.3.0 proposal #36232

Merged

danielleadams mentioned this pull request May 3, 2021

v14.17.0 proposal #38507

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

src: add loop idle time in diagnostic report #35940

src: add loop idle time in diagnostic report #35940

gireeshpunathil commented Nov 3, 2020 •

edited

Loading

richardlau commented Nov 3, 2020

gireeshpunathil commented Nov 3, 2020

cjihrig commented Nov 3, 2020

gireeshpunathil commented Nov 3, 2020

addaleax commented Nov 3, 2020

gireeshpunathil commented Nov 4, 2020

gireeshpunathil commented Nov 4, 2020

addaleax commented Nov 4, 2020 •

edited

Loading

gireeshpunathil commented Nov 4, 2020

richardlau left a comment •

edited

Loading

Trott left a comment

nodejs-github-bot commented Nov 10, 2020

trevnorris commented Nov 11, 2020

addaleax commented Nov 11, 2020

trevnorris commented Nov 11, 2020 •

edited

Loading

This comment has been minimized.

nodejs-github-bot commented Nov 11, 2020

gireeshpunathil commented Nov 12, 2020

cjihrig left a comment

cjihrig Nov 12, 2020

addaleax Nov 12, 2020

gireeshpunathil Nov 12, 2020

cjihrig Nov 12, 2020 •

edited

Loading

nodejs-github-bot commented Nov 12, 2020

gireeshpunathil commented Nov 13, 2020

nodejs-github-bot commented Nov 13, 2020

gireeshpunathil commented Nov 13, 2020

	// Functions are named to aid debugging when they are not called.
	const validators = {
	fs_event: common.mustCall(function fs_event_validator(handle) {
	if (!child_data.skip_fs_watch) {
	assert.strictEqual(handle.filename, expected_filename);
	assert(handle.is_referenced);
	}
	}),
	fs_poll: common.mustCall(function fs_poll_validator(handle) {
	assert.strictEqual(handle.filename, expected_filename);
	assert(handle.is_referenced);
	}),
	pipe: common.mustCallAtLeast(function pipe_validator(handle) {
	assert(handle.is_referenced);
	}),
	process: common.mustCall(function process_validator(handle) {
	assert.strictEqual(handle.pid, child_data.pid);
	assert(handle.is_referenced);
	}),
	tcp: common.mustCall(function tcp_validator(handle) {
	// TCP handles. The report should contain three sockets:
	// 1. The server's listening socket.
	// 2. The inbound socket making the request.
	// 3. The outbound socket sending the response.
	const port = child_data.tcp_address.port;
	if (handle.localEndpoint.port === port) {
	if (handle.remoteEndpoint === null) {
	found_tcp.push('listening');
	} else {
	found_tcp.push('inbound');
	}
	} else if (handle.remoteEndpoint.port === port) {
	found_tcp.push('outbound');
	}
	assert(handle.is_referenced);
	}, 3),
	timer: common.mustCallAtLeast(function timer_validator(handle) {
	assert(!handle.is_referenced);
	assert.strictEqual(handle.repeat, 0);
	}),
	udp: common.mustCall(function udp_validator(handle) {
	if (handle.remoteEndpoint === null) {
	assert.strictEqual(handle.localEndpoint.port,
	child_data.udp_address.port);
	found_udp.push('unconnected');
	} else {
	assert.strictEqual(handle.remoteEndpoint.port,
	child_data.udp_address.port);
	found_udp.push('connected');
	}
	assert(handle.is_referenced);
	}, 2),
	};

	uint64_t idle_time = uv_metrics_idle_time(env->event_loop());
	args.GetReturnValue().Set(1.0 * idle_time / 1e6);

src: add loop idle time in diagnostic report #35940

src: add loop idle time in diagnostic report #35940

Conversation

gireeshpunathil commented Nov 3, 2020 • edited Loading

Checklist

richardlau commented Nov 3, 2020

gireeshpunathil commented Nov 3, 2020

cjihrig commented Nov 3, 2020

gireeshpunathil commented Nov 3, 2020

addaleax commented Nov 3, 2020

gireeshpunathil commented Nov 4, 2020

gireeshpunathil commented Nov 4, 2020

addaleax commented Nov 4, 2020 • edited Loading

gireeshpunathil commented Nov 4, 2020

richardlau left a comment • edited Loading

Choose a reason for hiding this comment

Trott left a comment

Choose a reason for hiding this comment

nodejs-github-bot commented Nov 10, 2020

trevnorris commented Nov 11, 2020

addaleax commented Nov 11, 2020

trevnorris commented Nov 11, 2020 • edited Loading

This comment has been minimized.

nodejs-github-bot commented Nov 11, 2020

gireeshpunathil commented Nov 12, 2020

cjihrig left a comment

Choose a reason for hiding this comment

cjihrig Nov 12, 2020

Choose a reason for hiding this comment

addaleax Nov 12, 2020

Choose a reason for hiding this comment

gireeshpunathil Nov 12, 2020

Choose a reason for hiding this comment

cjihrig Nov 12, 2020 • edited Loading

Choose a reason for hiding this comment

nodejs-github-bot commented Nov 12, 2020

gireeshpunathil commented Nov 13, 2020

nodejs-github-bot commented Nov 13, 2020

gireeshpunathil commented Nov 13, 2020

gireeshpunathil commented Nov 3, 2020 •

edited

Loading

addaleax commented Nov 4, 2020 •

edited

Loading

richardlau left a comment •

edited

Loading

trevnorris commented Nov 11, 2020 •

edited

Loading

cjihrig Nov 12, 2020 •

edited

Loading