CPU occasionally spike after bumping to grpc-js 1.9.0

[schen22-9527]

Problem description

We have enabled o11y to our service. After bumping to grpc-js 1.9.0, CPU occasionally spikes.

Reproduction steps

Ref open-telemetry/opentelemetry-js#4082

Environment

• Node version: v14.21.3
• Package name and version: @grpc/grpc-js 1.9.0

[murgatroid99]

There are two things that would likely help determine the cause of this:

1. A CPU profile for a time period that includes a spike. See this documentation for how to get one.
2. A full gRPC trace log for a time period that includes a spike. The process will output this to stderr if you set the environment variables GRPC_TRACE=all and GRPC_VERBOSITY=DEBUG.

[schen22-9527]

I enabled GRPC_TRACE=all and GRPC_VERBOSITY=DEBUG last week, and part of the logs:

  | [2023-08-28 08:21:04,5909] - D 2023-08-28T08:21:04.590Z \| channel \| (1) dns:twpe-opentelemetry-collector.abumedia-k8s.svc.yahoo.local:4317 createResolvingCall [930] method="/opentelemetry.proto.collector.trace.v1.TraceService/Export", deadline=2023-08-28T08:21:14.590Z
  | [2023-08-28 08:21:04,5910] - D 2023-08-28T08:21:04.591Z \| resolving_call \| [930] Created
  | [2023-08-28 08:21:04,5910] - D 2023-08-28T08:21:04.591Z \| resolving_call \| [930] Deadline: 2023-08-28T08:21:14.590Z
  | [2023-08-28 08:21:04,5911] - D 2023-08-28T08:21:04.591Z \| resolving_call \| [930] Deadline will be reached in 9999ms
  | [2023-08-28 08:21:04,5912] - D 2023-08-28T08:21:04.591Z \| resolving_call \| [930] start called
  | [2023-08-28 08:21:04,5913] - D 2023-08-28T08:21:04.591Z \| resolving_call \| [930] startRead called
  | [2023-08-28 08:21:04,5915] - D 2023-08-28T08:21:04.591Z \| resolving_call \| [930] write() called with message of length 1875
  | [2023-08-28 08:21:04,5916] - D 2023-08-28T08:21:04.591Z \| resolving_call \| [930] halfClose called
  | [2023-08-28 08:21:04,5916] - D 2023-08-28T08:21:04.591Z \| channel \| (1) dns:twpe-opentelemetry-collector.abumedia-k8s.svc.yahoo.local:4317 createRetryingCall [931] method="/opentelemetry.proto.collector.trace.v1.TraceService/Export"
  | [2023-08-28 08:21:04,5916] - D 2023-08-28T08:21:04.591Z \| resolving_call \| [930] Created child [931]
  | [2023-08-28 08:21:04,5917] - D 2023-08-28T08:21:04.591Z \| retrying_call \| [931] start called
  | [2023-08-28 08:21:04,5917] - D 2023-08-28T08:21:04.591Z \| channel \| (1) dns:twpe-opentelemetry-collector.abumedia-k8s.svc.yahoo.local:4317 createLoadBalancingCall [932] method="/opentelemetry.proto.collector.trace.v1.TraceService/Export"
  | [2023-08-28 08:21:04,5917] - D 2023-08-28T08:21:04.591Z \| retrying_call \| [931] Created child call [932] for attempt 1
  | [2023-08-28 08:21:04,5917] - D 2023-08-28T08:21:04.591Z \| load_balancing_call \| [932] start called
  | [2023-08-28 08:21:04,5918] - D 2023-08-28T08:21:04.591Z \| load_balancing_call \| [932] Pick called
  | [2023-08-28 08:21:04,5918] - D 2023-08-28T08:21:04.591Z \| load_balancing_call \| [932] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 08:21:04,5918] - D 2023-08-28T08:21:04.591Z \| retrying_call \| [931] startRead called
  | [2023-08-28 08:21:04,5918] - D 2023-08-28T08:21:04.591Z \| load_balancing_call \| [932] startRead called
  | [2023-08-28 08:21:04,5922] - D 2023-08-28T08:21:04.592Z \| transport_flowctrl \| (4) 10.10.15.134:4317 local window size: 64975 remote window size: 65535
  | [2023-08-28 08:21:04,5922] - D 2023-08-28T08:21:04.592Z \| transport_internals \| (4) 10.10.15.134:4317 session.closed=false session.destroyed=false session.socket.destroyed=false
  | [2023-08-28 08:21:04,5923] - D 2023-08-28T08:21:04.592Z \| load_balancing_call \| [932] Created child call [933]
  | [2023-08-28 08:21:04,5923] - D 2023-08-28T08:21:04.592Z \| retrying_call \| [931] write() called with message of length 1880
  | [2023-08-28 08:21:04,5923] - D 2023-08-28T08:21:04.592Z \| load_balancing_call \| [932] write() called with message of length 1880
  | [2023-08-28 08:21:04,5924] - D 2023-08-28T08:21:04.592Z \| subchannel_call \| [933] write() called with message of length 1880
  | [2023-08-28 08:21:04,5924] - D 2023-08-28T08:21:04.592Z \| subchannel_call \| [933] sending data chunk of length 1880
  | [2023-08-28 08:21:04,5924] - D 2023-08-28T08:21:04.592Z \| retrying_call \| [931] halfClose called
  | [2023-08-28 08:21:04,5926] - D 2023-08-28T08:21:04.592Z \| load_balancing_call \| [932] halfClose called
  | [2023-08-28 08:21:04,5926] - D 2023-08-28T08:21:04.592Z \| subchannel_call \| [933] end() called
  | [2023-08-28 08:21:04,5927] - D 2023-08-28T08:21:04.592Z \| subchannel_call \| [933] calling end() on HTTP/2 stream
  | [2023-08-28 08:21:04,5933] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] Received server headers: 		:status: 200 		content-type: application/grpc
  | [2023-08-28 08:21:04,5934] - D 2023-08-28T08:21:04.593Z \| load_balancing_call \| [932] Received metadata
  | [2023-08-28 08:21:04,5934] - D 2023-08-28T08:21:04.593Z \| retrying_call \| [931] Received metadata from child [932]
  | [2023-08-28 08:21:04,5934] - D 2023-08-28T08:21:04.593Z \| retrying_call \| [931] Committing call [932] at index 0
  | [2023-08-28 08:21:04,5934] - D 2023-08-28T08:21:04.593Z \| resolving_call \| [930] Received metadata
  | [2023-08-28 08:21:04,5935] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] receive HTTP/2 data frame of length 7
  | [2023-08-28 08:21:04,5935] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] parsed message of length 7
  | [2023-08-28 08:21:04,5936] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] pushing to reader message of length 7
  | [2023-08-28 08:21:04,5936] - D 2023-08-28T08:21:04.593Z \| load_balancing_call \| [932] Received message
  | [2023-08-28 08:21:04,5936] - D 2023-08-28T08:21:04.593Z \| retrying_call \| [931] Received message from child [932]
  | [2023-08-28 08:21:04,5936] - D 2023-08-28T08:21:04.593Z \| resolving_call \| [930] Received message
  | [2023-08-28 08:21:04,5937] - D 2023-08-28T08:21:04.593Z \| resolving_call \| [930] Finished filtering received message
  | [2023-08-28 08:21:04,5937] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] Received server trailers: 		grpc-status: 0 		grpc-message:
  | [2023-08-28 08:21:04,5938] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] received status code 0 from server
  | [2023-08-28 08:21:04,5938] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] received status details string "" from server
  | [2023-08-28 08:21:04,5938] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] close http2 stream with code 0
  | [2023-08-28 08:21:04,5939] - D 2023-08-28T08:21:04.593Z \| subchannel_call \| [933] ended with status: code=0 details=""
  | [2023-08-28 08:21:04,5940] - D 2023-08-28T08:21:04.594Z \| load_balancing_call \| [932] Received status
  | [2023-08-28 08:21:04,5940] - D 2023-08-28T08:21:04.594Z \| load_balancing_call \| [932] ended with status: code=0 details=""
  | [2023-08-28 08:21:04,5940] - D 2023-08-28T08:21:04.594Z \| retrying_call \| [931] Received status from child [932]
  | [2023-08-28 08:21:04,5940] - D 2023-08-28T08:21:04.594Z \| retrying_call \| [931] state=COMMITTED handling status with progress PROCESSED from child [932] in state ACTIVE


...

Since there're bunch of messages there.. I can provide more if it's not enough to address issue.
For CPU profile, I'll provide you asap

[murgatroid99]

These logs are for a 5 millisecond time span. Does that correspond to a CPU usage spike?

[schen22-9527]

sorry my fault.. I picked the wrong period
the peak period logs:

  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7447] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7448] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick called
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Picked subchannel (2) 10.10.15.134:4317 has state IDLE after getting credentials metadata. Retrying pick
  | [2023-08-28 09:24:02,7449] - D 2023-08-28T09:24:02.744Z \| load_balancing_call \| [1284] Pick result: COMPLETE subchannel: (2) 10.10.15.134:4317 status: undefined undefined

It has a lot of load balancing call for pick, which may related to #2511 in 1.9.0

[murgatroid99]

I think this is the bug that is fixed by #2559. I'll get that fix out today.

[murgatroid99]

That fix is out in version 1.9.2. Please try it out.

[schen22-9527]

confirmed the issue fixed. Thanks @murgatroid99 !