Spans Get Lost

[DaGeRe]

Prerequisites

• I have checked the FAQ, and issues and found no answer.

I am trying to profile every method call in pinpoint, so my goal is to get the execution time of each method span within a set of traces.

To do so, I've changed the agent's pinpoint.config:

profiler.entrypoint=moobench.application.MonitoredClassSimple.monitoredMethod
profiler.pinpoint.base-package=moobench.application
profiler.include=moobench.application*

profiler.sampling.type=COUNTING
profiler.sampling.counting.sampling-rate=1

Using this configuration, I would expected the monitoredMethod to be profiled every time (since I set profiling to COUNTING and the rate to 1. Unfortunately, not all the traces arrive - I would guess roughly 50% arrive (but its also different on every start of my application).

I've added a debug output to

pinpoint/agent-module/profiler/src/main/java/com/navercorp/pinpoint/profiler/sender/grpc/GrpcDataSender.java

Line 57 in 7075663

if (this.queue.offer(data)) {

, and saw that 100% of the traces are sent. Furthermore, I've added a debug output to

pinpoint/collector/src/main/java/com/navercorp/pinpoint/collector/receiver/grpc/flow/RateLimitClientStreamServerInterceptor.java

Line 77 in 7075663

if (bucket.tryConsume(1)) {

, and saw that ~50% of the traces arrive.

Therefore, they seem to be lost somewhere in the middle, but all my tries to locate the part of the code where the traces are omitted haven't led to success.

Is there anywhere else, where traces are selected / sampled, besides the agent-side sampling? And is there a way to reduce this, so I receive 100% of the traces?

[DaGeRe]

After some debugging, it shows that SpanGrpcDataSender.MessageDispatcher.onDispatch is called less often:

pinpoint/agent-module/profiler/src/main/java/com/navercorp/pinpoint/profiler/sender/grpc/SpanGrpcDataSender.java

Line 69 in 7075663

final GeneratedMessageV3 message = messageConverter.toMessage(data);

If I create 100'000 traces, roughly 60'000 calls to SpanGrpcDataSender.MessageDispatcher.onDispatch happen, and roughly 55'000 traces are finally stored into hbase.

It seems like this is caused by stream.isReady() being false in

pinpoint/agent-module/profiler/src/main/java/com/navercorp/pinpoint/profiler/sender/grpc/stream/DefaultStreamTask.java

Line 90 in 7075663

if (stream.isReady()) {

From here, I don't really know how to proceed, is there maybe just some buffer I could increase to make the ClientCallStateStreamObserver ready more often / being able to process more traces?

[emeroad]

Depending on HBase performance, collected information may not be stored.

The HBase image provided in the sample is not intended for production use.
In a production environment, HBase must be installed in Fully Distributed Mode.

[DaGeRe]

Thanks for the hint.

My hbase and kafka are started like this:

	docker run -d \
		--name hbase \
		--hostname hbase \
		--net=host \
		--entrypoint /bin/sh \
		openeuler/hbase:2.6.3-oe2403sp1 \
		-c "
hostname() { cat /etc/hostname; }
export -f hostname

sed -i '/<configuration>/a <property><name>hbase.zookeeper.property.clientPortAddress</name><value>0.0.0.0</value></property>' /usr/local/hbase/conf/hbase-site.xml

sed -i '/<configuration>/a <property><name>hbase.master.hostname</name><value>localhost</value></property>' /usr/local/hbase/conf/hbase-site.xml
sed -i '/<configuration>/a <property><name>hbase.master.port</name><value>16000</value></property>' /usr/local/hbase/conf/hbase-site.xml


/usr/local/hbase/bin/start-hbase.sh && tail -F /usr/local/hbase/logs/*
"
	docker run -d \
		--name kafka \
		--net=host \
		-e KAFKA_NODE_ID=1 \
		-e KAFKA_PROCESS_ROLES=broker,controller \
		-e KAFKA_LISTENERS=PLAINTEXT://:9092,CONTROLLER://:9093 \
		-e KAFKA_ADVERTISED_LISTENERS=PLAINTEXT://localhost:9092 \
		-e KAFKA_CONTROLLER_LISTENER_NAMES=CONTROLLER \
		-e KAFKA_INTER_BROKER_LISTENER_NAME=PLAINTEXT \
		-e KAFKA_CONTROLLER_QUORUM_VOTERS=1@localhost:9093 \
		-e CLUSTER_ID=abcdefghijklmnopqrstuv \
		confluentinc/cp-kafka:7.6.0

So it is not the sample hbase, but an hbase that seems fully functional to me.

Anyhow, after further debugging, it seems to me like somewhere in the processes of pinpoint itself, spans get lost.

If I add a debug output in DefaultStreamTask.dispatch (

pinpoint/agent-module/profiler/src/main/java/com/navercorp/pinpoint/profiler/sender/grpc/stream/DefaultStreamTask.java

Line 89 in 9be4559

final M message = queue.take();

), and execute my traced method 100.000 times, this output is printed 100.002 times (don't know why the 2 additional calls are produced, anyhow, this seems fine to me) -- same happens for GrpcDataSender.send, so I assume all data are sent correctly from the instrumented application.

But if I add output in the collector to RateLimitClientStreamServerInterceptor.interceptCall.onMessage (

pinpoint/collector/src/main/java/com/navercorp/pinpoint/collector/receiver/grpc/flow/RateLimitClientStreamServerInterceptor.java

Line 77 in 9be4559

if (bucket.tryConsume(1)) {

), this is called less often; in my last try, it was executed 66788 times. This means, that before the rate limit is checked, packets are somehow lost "on the way".

Ive set -Dcollector.receiver.grpc.span.stream.flow-control.rate-limit.capacity=100000` for the collector, so all 100k traces should arrive.

This is quite hard to debug for me, since the traces seem to be sent and the first point where they arrive via gRPC seems to receive incomplete traces. Do you have any hint why this might be happening / how to further debug this behavior?

[emeroad]

There is a limit setting to prevent OOM caused by excessive trace.

## Agent Level Defense Measures
- profiler.callstack.max.depth=64
// Defense OOM caused by infinite loops

## Collector Level Defense
collector.spanEvent.sequence.limit=5000
// Maximum number of events per span(1 request)

The above defense settings are absolutely necessary.

Data transmission between the Agent and Collector uses a chunked format, with no limit on the total data size.
However, since the web server must read all data at once, this can potentially cause an OOM.

[DaGeRe]

Thanks for the feedback. Adding

## Call Stack
# Set max depth, if -1 is unlimited and min is 2.
profiler.callstack.max.depth=256
profiler.callstack.overflow.log.ration=10000

collector.spanEvent.sequence.limit=100000

to the pinpoint config unfortunately did not change anything. In my scenario, I receive a lot of traces with a call tree depth 11. So I guess the call tree depth shouldn't be an issue.

Is it sufficient to set collector.spanEvent.sequence.limit in the pinpoint.config of the agent? (in my case, agent-module/agent/target/pinpoint-agent-3.0.3/profiles/release/pinpoint.config -- which basically works, if I activate sampling, fewer traces arrive). Or do I need to set it at the collector somehow? I also tried setting the collector property using -Dcollector.spanEvent.sequence.limit=5000 as start parameter of the collector, but this also did not change anything.