Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Research replacing recordConsume instrumentation wrapping with record #981

Closed
bizob2828 opened this issue Nov 16, 2021 · 4 comments · Fixed by #2207
Closed

Research replacing recordConsume instrumentation wrapping with record #981

bizob2828 opened this issue Nov 16, 2021 · 4 comments · Fixed by #2207
Assignees
@bizob2828
Labels
points: 5 1-2 weeks sync2jira
Projects
Node.js Engineering Board

Comments

@bizob2828
Copy link
Member

We found a bug in recordConsume #977 and we made a quick fix. This ticket will serve as a research/prototype to investigate whether or not we can just use this.record within recordConsume instead of this.wrap. It looks like for this method we made up a messageHandler spec key which executes after a callback finishes or promise resolves and we copy parameters to the segment. I'm wondering if we can just use spec.after to achieve this? But also since this API is exposed would it be a breaking change?
@bizob2828 bizob2828 added this to Triage Needed: Unprioritized Features in Node.js Engineering Board via automation Nov 16, 2021
@bizob2828 bizob2828 mentioned this issue Nov 17, 2021
Merged
@coreyarnold coreyarnold added the points: 3 A few days label Feb 23, 2022
@coreyarnold coreyarnold moved this from Triage Needed: Unprioritized Features to To do: Features here are prioritized in Node.js Engineering Board Mar 2, 2022
@workato-integration
Copy link

https://issues.newrelic.com/browse/NEWRELIC-4462

jordigh pushed a commit to jordigh/node-newrelic that referenced this issue Mar 27, 2023
NEWRELIC-5296: (recordConsume) reduce its cognitive complexity
3b302b8 
Also closes newrelic#981, since it removes the biggest use of `shim.wrap` with
`this.record`.
jordigh pushed a commit to jordigh/node-newrelic that referenced this issue Mar 29, 2023
NEWRELIC-5296: (recordConsume) reduce its cognitive complexity
50e0feb 
Also closes newrelic#981, since it removes the biggest use of `shim.wrap` with
`this.record`.
jordigh pushed a commit to jordigh/node-newrelic that referenced this issue Mar 30, 2023
NEWRELIC-5296: (recordConsume) reduce its cognitive complexity
48b9931 
Also closes newrelic#981, since it removes the biggest use of `shim.wrap` with
`this.record`. The resulting function is much simpler!
@jordigh jordigh mentioned this issue Mar 30, 2023
Closed
jordigh pushed a commit to jordigh/node-newrelic that referenced this issue Apr 16, 2023
NEWRELIC-5296: (recordConsume) reduce its cognitive complexity
09c858d 
Also closes newrelic#981, since it removes the biggest use of `shim.wrap` with
`this.record`. The resulting function is much simpler!
@kmudduluru kmudduluru moved this from To do: Features here are prioritized to Triage Needed: Unprioritized Features in Node.js Engineering Board Feb 27, 2024
@kmudduluru kmudduluru moved this from Triage Needed: Unprioritized Features to To do: Features here are prioritized for this sprint in Node.js Engineering Board May 8, 2024
@jsumners-nr jsumners-nr moved this from To do: Features here are prioritized for this sprint to In progress: Issues being worked on in Node.js Engineering Board May 9, 2024
@jsumners-nr jsumners-nr self-assigned this May 9, 2024
@jsumners-nr jsumners-nr mentioned this issue May 9, 2024
Closed
@jsumners-nr
Copy link
Contributor

Some notes.

When stepping through the test:

node-newrelic/test/unit/shim/message-shim.test.js

Lines 451 to 465 in 957529e

t.test('should create a consume segment', function (t) {
shim.recordConsume(wrappable, 'getActiveSegment', function () {
return { destinationName: 'foobar' }
})
helper.runInTransaction(agent, function (tx) {
const startingSegment = agent.tracer.getSegment()
const segment = wrappable.getActiveSegment()
t.not(segment, startingSegment)
t.equal(segment.transaction, tx)
t.equal(segment.name, 'MessageBroker/RabbitMQ/Exchange/Consume/Named/foobar')
t.equal(agent.tracer.getSegment(), startingSegment)
t.end()
})
})

With the following line using this.wrap and this.record:

node-newrelic/lib/shim/message-shim/index.js

Line 294 in 8af22b8

return this.record(nodule, properties, function wrapConsume(shim, fn, fnName) {

We get the following (rough) traces:

this.wrap 
1. message-shim.test.js ~ 452 (`test`)
	1. message-shim/index.js ~ 284 (`recordConsume`)
		1. shim.js ~ 301 (`wrap`)
			1. wraps `getActiveSegment` at line 343
				1. shim.js ~ 1717 (`_wrap`)
					1. message-shim/index.js ~ 295 (`wrapConsume`)
						1. consume.js ~ 126 (`createRecorder`)
2. message-shim.test.js ~ 456 (`test`)
	1. agent_helper.js ~ 271 (`runInTransaction`)
		1. tracer/index.js ~ 143 (`transactionNestProxy`)
			1. tracer/index.js ~ 154 (`wrapTransactionInvocation`)
				1. tracer/index.js ~ 183 (`bindFunction`)
					1. tracer/index.js ~ 190 (`_makeWrapped`)
			2. tracer/index.js ~ 192 (`wrapped`) ???
				1. async-local-context-manager.js ~ 59 (`runInContext`)
					1. agent_helper.js ~ 288 (`transactionNestProxy`)
						1. message-shim.test.js ~ 457 (`runInTransaction` callback)
							1. tracer/index.js ~ 57 (`getSegment`)
								1. async-local-context-manager.js ~ 35 (`getContext`)
						2. message-shim.test.js ~ 458 (`runInTransaction` callback) <diverges />
							1. consume.js ~ 127 (`consumeRecorder`)
								1. shim.js ~ 1056 `getSegment`
									1. async-local-context-manager.js ~ 35 (`getContext`)
								2. transaction/index.js ~ 195 (`isActive`)
									1. timer.js ~ 119 (`isActive`)
								3. shim.js ~ 1400 (`argsToArray`)
								4. consume.js ~ 26 (`updateSpecFromArgs`)
									1. shim.js ~ 1288 (`isFunction`)
									2. message-shim.test.js ~ 453 (`recordConsume` callback)
								5. common.js ~ 20 (`_nameMessageSegment`) *** <= where the desired name comes from
								6. shim.js ~ 1197 (`createSegment`)
									1. shim.js ~ 1299 (`isSting`)
									2. shim.js ~ 1231 (`_rawCreateSegment`)
										1. shim.js ~ 83 (`getTracer`)
										2. tracer/index.js ~ 67 (`createSegment`)
											1. transaction/index.js ~ 195 (`isActive`)
												1. timer.js ~ 119 (`isActive`)
											2. segment.js ~ 241 (`add`)
												1. segment.js ~ 43 (`TraceSegment`)
													1. transaction/index.js ~ 685 (`addRecorder`)
													2. attributes.js ~ 29 (`constructor`)
														1. attributes.js ~ 174 (`makeFilter`)
															1. config/index.js ~ 1780 (`getInstance`)
													3. hashes.js ~ 87 (`makeId`)
													4. timer.js ~ 33 (`Timer`)
													5. segment.js ~ 129 (`probe`)
								7. shim.js ~ 72 (`getAgent`) 
								8. shim.js ~ 1288 (`isFunction`)
								9. consume.js ~ 53 (`bindCallback`)
									1. shim.js ~ 1420 (`normalizeIndex`)
									2. shim.js ~ 994 (`bindCallbackSegment`)
										1. shim.js ~ 1310 (`isNumber`)
										2. shim.js ~ 1288 (`isFunction`)
								10. consume.js ~ 95 (`bindConsumer`)
									1. shim.js ~ 1138 (`applySegment`)
										1. shim.js ~ 1288 (`isFunction`)
										2. async-local-context-manager.js ~ 35 (`getContext`)
										3. async-local-context-manager.js ~ 59 (`runInContext`)
											1. shim.js ~ 1153 (`runInContextCb`)
												1. segement.js ~ 186 (`start`)
													1. timer.js ~ 47 (`begin`)
												2. message-shim.test.js ~ 50 (`getActiveSegment`)
													1. tracer/index.js ~ 57 (`getSegment`)
														1. async-local-context-manager.js ~ 35 (`getContext`)
											2. segment.js ~ 175 (`touch`)
												1. segment.js ~ 129 (`probe`)
												2. timer.js ~ 75 (`touch`)
												3. segment.js ~ 217 (`_updateRootTimer`)
													1. timer.js ~ 227 (`endsAfter` / `compare`)
														1. timer.js ~ 175 (`getDurationInMillis`)
															1. timer.js ~ 25 (`hrToMillis`)
														2. timer.js ~ 175 (`getDurationInMillis`)
															1. timer.js ~ 25 (`hrToMillis`)
						3. At this point we should have the correct segment with the correct name.
this.record 
1. message-shim.test.js ~ 452 (`test`)
	1. message-shim/index.js ~ 284 (`recordConsume`)
		1. shim.js ~ 636 (`record`)
			1. shim.js ~ 301 (`wrap`)
				1. wraps `getActiveSegment` at line 343
					1. shim.js ~ 1717 (`_wrap`)
						1. shim.js ~ 643 (`makeWrapper`)
							1. shim.js ~ 668 (`recordWrapper`)
2. message-shim.test.js ~ 456 (`test`)
	1. agent_helper.js ~ 271 (`runInTransaction`)
		1. tracer/index.js ~ 143 (`transactionNestProxy`)
			1. tracer/index.js ~ 154 (`wrapTransactionInvocation`)
				1. tracer/index.js ~ 183 (`bindFunction`)
					1. tracer/index.js ~ 190 (`_makeWrapped`)
			2. tracer/index.js ~ 196 (`wrapped`) ???
				1. async-local-context-manager.js ~ 59 (`runInContext`)
					1. agent_helper.js ~ 288 (`transactionNestProxy`)
						1. message-shim.test.js ~ 457 (`runInTransaction` callback)
							1. tracer/index.js ~ 57 (`getSegment`)
								1. async-local-context-manager.js ~ 35 (`getContext`)
						2. message-shim.test.js ~ 458 (`runInTransaction` callback) <diverges />
							1. shim.js ~ 670 (`wrapper`)
								1. shim.js ~ 1400 (`argsToArray`)
								2. message-shim/index.js ~ 295 (`wrapConsume` callback)
									1. shim.js ~ 1288 (`isFunction`)
									2. consume.js ~ 126 (`createRecorder`)
								3. shim.js ~ 1079 (`getActiveSegment`)
									1. shim.js ~ 1056 (`getSegment`)
										1. async-local-context-manager.js ~ 35 (`getContext`)
									2. transaction/index.js ~ 195 (`isActive`)
										1. timer.js ~ 119 (`isActive`)
								5. shim.js ~ 1231 (`_rawCreateSegment`)
									1. shim.js ~ 1079 (`getActiveSegment`)
										1. shim.js ~ 1056 (`getSegment`)
											1. async-local-context-manager.js ~ 35 (`getContext`)
										2. transaction/index.js ~ 195 (`isActive`)
											1. timer.js ~ 119 (`isActive`)
									2. shim.js ~ 83 (`getTracer`)
									3. tracer/index.js ~ 67 (`createSegment`)
										1. transaction/index.js ~ 195 (`isActive`)
											1. timer.js ~ 119 (`isActive`)
										2. segment.js ~ 241 (`add`)
											1. segment.js ~ 43 (`TraceSegment`)
												1. attributes.js ~ 29 (`constructor`)
													1. attributes.js ~ 174 (`makeFilter`)
														1. config/index.js ~ 1780 (`getInstance`)
												2. hashes.js ~ 87 (`makeId`)
												3. timer.js ~ 33 (`Timer`)
												4. segment.js ~ 129 (`probe`)
								6. code-level-metrics.js ~ 50 (`addCLMAttributes`)
								7. shim.js ~ 751 (`_doRecord`)
									1. shim.js ~ 1791 (`_bindAllCallbacks`)
										1. shim.js ~ 1835 (`_bindCallback`)
											1. shim.js ~ 1288 (`isFunction`)
											2. shim.js ~ 1310 (`isNumber`)
										2. shim.js ~ 1835 (`_bindCallback`)
											1. shim.js ~ 1288 (`isFunction`)
											2. shim.js ~ 1310 (`isNumber`)
									2. shim.js ~ 792 (`_applyRecorderSegment`)
										1. shim.js ~ 1138 (`applySegment`)
											1. shim.js ~ 1288 (`isFunction`)
											2. async-local-context-manager.js ~ 35 (`getContext`)
											3. async-local-context-manager.js ~ 59 (`runInContext`)
												1. shim.js ~ 1153 (`runInContextCb`)
													1. segment.js ~ 186 (`start`)
														1. timer.js ~ 47 (`begin`)
													2. message-shim.test.js ~ 50 (`getActiveSegment`)
														1. tracer/index.js ~ 57 (`getSegment`)
															1. async-local-context-manager.js ~ 35 (`getContext`)
													3. segment.js ~ 175 (`touch`)
														1. segment.js ~ 129 (`probe`)
														1. timer.js ~ 75 (`touch`)
														2. segment.js ~ 217 (`_updateRootTimer`)
															1. timer.js ~ 227 (`endsAfter` / `compare`)
																1. timer.js ~ 175 (`getDurationInMillis`)
																	1. timer.js ~ 25 (`hrToMillis`)
																2. timer.js ~ 175 (`getDurationInMillis`)
																	1. timer.js ~ 25 (`hrToMillis`)
						3. At this point we should have the correct segment with the correct name.

At the moment, all I am able to discern from this is that this.wrap ends up invoking _nameMessageSegment function where as the this.record path does not.

@bizob2828
Copy link
Member Author

At the moment, all I am able to discern from this is that this.wrap ends up invoking _nameMessageSegment function where as the this.record path does not.

This is because record requires you to pass in the name as part of the spec.

@bizob2828 bizob2828 assigned bizob2828 and unassigned jsumners-nr May 20, 2024
@bizob2828
Copy link
Member Author

I have ideas here but it's just easier for me to do it instead of reporting back

@bizob2828 bizob2828 added points: 5 1-2 weeks and removed points: 3 A few days labels May 22, 2024
@bizob2828 bizob2828 mentioned this issue May 22, 2024
Merged
@bizob2828 bizob2828 moved this from In progress: Issues being worked on to Needs PR Review in Node.js Engineering Board May 22, 2024
Node.js Engineering Board automation moved this from Needs PR Review to Done: Issues recently completed May 24, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@bizob2828 bizob2828

Labels
points: 5 1-2 weeks sync2jira
Projects
Node.js Engineering Board
  
Done: Issues recently completed
Milestone
No milestone
3 participants
@coreyarnold @bizob2828 @jsumners-nr