Skip to content

NMS-14748: Raw message counts for Minion performance testing - #9073

Open
joseanesONMS wants to merge 3 commits into
developfrom
jira/NMS-14748-minion-message-metrics-smoke
Open

joseanesONMS wants to merge 3 commits into
developfrom
jira/NMS-14748-minion-message-metrics-smoke

Conversation

@joseanesONMS

Copy link
Copy Markdown
Contributor

Adds per-message counters so a Minion performance test can confirm every packet the load generator sent was received and processed.

The Sink dispatch counter in metrics-display counts batches, so the remaining gaps were syslog packets on Minion and individual messages received from the broker on core.

  • Syslog listeners (Camel Netty and java.net) count every datagram as packetsReceived in a new "Syslog Listener" metric set on Minion, also exported over JMX (org.opennms.netmgt.syslogd.listener).
  • Core syslogd counts individual messages per batch (consumer.messagesReceived); its registry is now registered for metrics-display too.
  • Telemetryd and Sentinel count messages per queue (consumers.<queue>.messagesReceived); for flows these are records, comparable with the Minion parser's recordsDispatched.
  • Traps (rawTrapsReceived on Minion, the Trapd MBean on core) and NetFlow packet counts per listener/parser already existed and are unchanged.
  • New tests send real UDP packets through both syslog listeners and check both consumer counts; the existing syslog listener and Blueprint ITs pass locally. The new counters are not added to the Minion JMX collection or graphs.

External References

Performance tests could not confirm that every packet a load generator
sent was received and processed, because metrics-display only showed the
Sink dispatch counter, which counts batches. The syslog listeners now
count every datagram (packetsReceived) in a "Syslog Listener" metric set
on Minion, also exported over JMX; on core the receiver uses the Syslogd
registry, which is now registered for metrics-display as well.

On the consuming side, syslogd counts individual messages in each batch
(consumer.messagesReceived) and telemetryd/Sentinel count messages per
queue (consumers.<queue>.messagesReceived). Traps already had both counts
(rawTrapsReceived on Minion, the Trapd MBean on core), and NetFlow packet
counts already existed per listener and parser on Minion. The Syslogd and
Telemetryd reference pages list which counters to compare.

@marshallmassengill marshallmassengill left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks good. I checked the wiring and benchmarked this: about 43 ns per datagram with no allocation or locks, around 1% of a core at 200k/s.

  • The docs should note that core's consumer.messagesReceived adds up all Minions plus core's own listener (and resets on restart).

  • In SyslogReceiverPacketMetricsIT, a warm-up packet arriving after the 1s sleep would break the exact assertEquals. Checking >= would avoid that, or the test could wait until the count stops changing before taking the baseline.

…tion

Review feedback: a warm-up packet arriving after the fixed one-second pause
would break the exact packet count, so the test now takes its baseline only
once the counter stops changing. The Syslogd and Telemetryd pages now say
that the core and Sentinel message counters add up every Minion plus their
own listeners, and that all of the counters reset when the process restarts.
@joseanesONMS

Copy link
Copy Markdown
Contributor Author

@marshallmassengill both addressed in 796aaf9:

  • The Syslogd and Telemetryd pages now say the core/Sentinel message counters add up every Minion plus their own listeners, and that all counters reset on restart, so counts should be compared over the same interval.
  • SyslogReceiverPacketMetricsIT now takes its baseline only once the packet counter has stopped changing (polled every 500 ms), instead of after a fixed 1 s sleep; it passed 5 runs in a row locally.

@cgorantla cgorantla left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this needs to be validated with real environment to understand if we are really mapping apples to apples.

@cgorantla cgorantla left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One existing bug

m_packetsReceived.mark();

// Create a metric for the Syslog packet size
packetSizeHistogram.update(length);

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
packetSizeHistogram.update(length);
packetSizeHistogram.update(pkt.getLength());

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Applied in e01e54f, thanks. The histogram was recording the receive buffer size for every packet.

…togram

The JavaNet receiver recorded the receive buffer size for every packet, so the packetSize histogram showed a constant value instead of the size of each syslog datagram.
@joseanesONMS

Copy link
Copy Markdown
Contributor Author

@cgorantla I validated this on a real Horizon + Minion + PostgreSQL stack built from this branch, sending 1,000 syslog messages over UDP to the Minion:

Count Value
Sent by the client 1000
Minion Syslog Listener packetsReceived 513
Minion sink Syslog.dropped 0
Core Syslogd consumer.messagesReceived 513
Events stored 513

The listener count, the core consumer count and the stored events match one for one, so the counters compare the same messages. The 487 missing messages never reached the Minion's socket; they were lost in UDP forwarding into the container (Docker Desktop under emulation), which is the case where comparing a sender's count with packetsReceived shows loss outside OpenNMS. The packet-size fix you suggested is in e01e54f.

@marshallmassengill

Copy link
Copy Markdown
Contributor

The 487 missing messages never reached the Minion's socket; they were lost in UDP forwarding into the container

So you intentionally lost half the packets?

@joseanesONMS

Copy link
Copy Markdown
Contributor Author

@marshallmassengill no. The helper sends all datagrams in one tight burst, and my explanation of where they were lost was wrong. I re-ran the stack in two phases and read the Minion container's kernel UDP counters (/proc/net/snmp) around each phase:

Sent Kernel delivered Kernel RcvbufErrors Minion packetsReceived Core consumer.messagesReceived Events stored
Paced (5 ms apart) 1000 1000 0 1000 1000 1000
Burst 1000 834 166 834 834 834

(The kernel's delivered count also includes 4 to 8 unrelated datagrams per phase, which I've left out.) Paced, nothing is lost. In the burst, every datagram reaches the Minion's kernel, and 166 are dropped there because the listener's socket receive buffer is full. That is before the application reads them, so packetsReceived can't count them. The three OpenNMS counters agree with each other in both phases. Kernel buffer drops show up only in RcvbufErrors (netstat -su on the Minion host).

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants