Broker Statistics

The following statistics are provided as a basic useful minimum.

1. Peak bytes per second
2. Current bytes per second
3. Total bytes
4. Peak messages per second
5. Current messages per second
6. Total messages

These statistics will be generated for both delivered and received messages, per connection and aggregated per virtualhost and also for the entire broker. Delivered messages are those that have been sent to a client by the broker, and may be counted more than once die to rollbacks and re-delivery. Received messages are those that are published by a client and received by the broker.

Mechanism

The statistics are generated using a sample counter, which is thread-safe and is triggered on incoming message events. The totals for messages and data (bytes) are recorded as type long and the rates are recorded as double since they may be fractional.

The default sample period is one second, during which events are recorded cumulatively. This can be changed for all counters in the broker by setting the system property qpid.statistics.samplePeriod. Basically, rates are calculated as an average over this sample period, so if the traffic is very bursty, a small sample period will fail to capture events most of the time, and you will end up with inflated peak rates. Since we are calculating rates per-second, the sample period is 1000ms as a default, but if this is increased to, say, 10000ms then messages will be counted over ten second periods, and the resulting totals divided by ten to give the rate.

When all statistics generation is enabled, there will be 12 counters that are used, since statistics are calculated for the product of the following sets:

{ Broker, Virtualhost, Connection } x { Delivery, Receipt } x { Messages, Data }

Reporting

If statistics are being generated for the broker or for virtualhosts then periodic reporting can be enabled. This is generated at specified intervals, with the option to reset the statistics after outputting the current data.

[Statistics-Reporting] BRK-1008 : received : 4.395 kB/s peak : 4500 bytes total
[Statistics-Reporting] BRK-1008 : delivered : 4.395 kB/s peak : 4500 bytes total
[Statistics-Reporting] BRK-1009 : received : 45 msg/s peak : 45 msgs total
[Statistics-Reporting] BRK-1009 : delivered : 45 msg/s peak : 45 msgs total
[Statistics-Reporting] VHT-1003 : localhost : received : 1.465 kB/s peak : 1500 bytes total
[Statistics-Reporting] VHT-1003 : localhost : delivered : 1.465 kB/s peak : 1500 bytes total
[Statistics-Reporting] VHT-1004 : localhost : received : 15 msg/s peak : 15 msgs total
[Statistics-Reporting] VHT-1004 : localhost : delivered : 15 msg/s peak : 15 msgs total
[Statistics-Reporting] VHT-1003 : test : received : 0.977 kB/s peak : 1000 bytes total
[Statistics-Reporting] VHT-1003 : test : delivered : 0.977 kB/s peak : 1000 bytes total
[Statistics-Reporting] VHT-1004 : test : received : 10 msg/s peak : 10 msgs total
[Statistics-Reporting] VHT-1004 : test : delivered : 10 msg/s peak : 10 msgs total
[Statistics-Reporting] VHT-1003 : development : received : 1.953 kB/s peak : 2000 bytes total
[Statistics-Reporting] VHT-1003 : development : delivered : 1.953 kB/s peak : 2000 bytes total
[Statistics-Reporting] VHT-1003 : development : received : 1.953 kB/s peak : 2000 bytes total
[Statistics-Reporting] VHT-1003 : development : delivered : 1.953 kB/s peak : 2000 bytes total
[Statistics-Reporting] VHT-1004 : development : received : 20 msg/s peak : 20 msgs total
[Statistics-Reporting] VHT-1004 : development : delivered : 20 msg/s peak : 20 msgs total

Sample statistics report log messages

The reported statistics are output using the operational logging mechanism, and can therefore be extracted from the log files using the same mechanisms as are currently used for other such messages. The new message types are as follows:

• BRK-1008 - Broker data statistics (peak bytes per second and total bytes)
• BRK-1009 - Broker message statistics (peak messages per second and total messages)
• VHT-1003 - Virtualhost data statistics (peak bytes per second and total bytes)
• VHT-1004 - Virtualhost message statistics (peak messages per second and total messages)

Configuration

The statistics generation will be configured via the config.xml broker configuration mechanism.

<statistics>
    <generation>
        <!-- default false -->
        <broker>true</broker>
        <virtualhosts>true</virtualhosts>
        <connections>true</connections>
    </generation>
    <reporting>
        <period>3600</period><!-- seconds -->
        <reset>true</reset>
    </reporting>
</statistics>

It is not possible to enable statistics generation for a single virtualhost - all virtualhosts will generate statistics if the //statistics/generation/virtualhosts element is set to true.

It only makes sense to enable reporting if either broker or virtualhosts have statistics generation enabled also. However, the broker will simply ignore the reporting configuration if no statistics are being generated. If the //statistics/reporting/reset element is set to true then after reporting on the statistics in the log, the statistics will be reset to zero for the entire broker.

Even if statistics generation is completely disabled, it is still possible to activate statistics on an individual connection, while the broker is running. The JMX attribute statisticsEnabled on a connection MBean can be set to true which will start statistics generation, and totals and rates will be calculated from this point onward, or until it is set to false again.

Additionally, the following two system properties can be set to configure the statistics counter:

• qpid.statistics.samplePeriod - sample period in ms - default 1000
• qpid.statistics.disable - override configuration and disable statistics collection - default false (not set)

These two properties are exposed on the StatisticsCounter class as static fields DEFAULT_SAMPLE_PERIOD and DISABLE_STATISTICS.

Design

StatisticsCounter Class

This implements the counting of event data and generates the total and rate statistics. There should be one instance of this class per type of statistic, such as messages or bytes. The instance methods that are called to add an event are:

• void registerEvent()
  Registers a single event at the current system time, such as the arrival of a message.

• void registerEvent(long value)
  Registers a cumulative value, such as the size of a message, at the current system time.

• void registerEvent(long value, long timestamp)
  Registers a cumulative value at the specified time. As with the previous method, this could be 1, which will allow timestamped single events to be registered if the no-argument version is not sufficient.

There are three constructors:

• StatisticsCounter()
• StatisticsCounter(String name)
• StatisticsCounter(String name, long samplePeriod)

These are chained in that order, using a default name of counter and the default sample period of 2000 ms or set in the qpid.statistics.samplePeriod property.

To retrieve the data, there are methods to return the current rate, peak rate and total, as well as the start time, sample period and name of the counter, and also a method to reset the counter.

StatisticsGatherer Interface

This is implemented by the broker business object that is generating statistics. It provides the following methods:

• void initialiseStatistics()
• void registerMessageReceived(long messageSize, long timestamp)
• void registerMessageDelivered(long messageSize)
• StatisticsCounter getMessageDeliveryStatistics()
• StatisticsCounter getDataDeliveryStatistics()
• StatisticsCounter getMessageReceiptStatistics()
• StatisticsCounter getDataReceiptStatistics()
• void resetStatistics()
• void setStatisticsEnabled(boolean enabled)
• boolean isStatisticsEnabled()

These statistics are exposed using the separate JMX Mbean interfaces detailed below, which calls these methods to retrieve the underlying StatisticsCounter objects and return their attributes. This interface gives a standard way for parts of the broker to set up and configure statistics generation.

When creating these objects, there should be a parent/child relationship between them, normally from broker to virtualhost to connection. This means that the lowest level gatherer can record statistics (if enabled) and also pass on the notification to its parent object to allow higher level aggregation of statistics. When resetting statistics, this works in the opposite direction, with higher level gatherers also resetting all of their child objects. Note that this parent/choild relationship is never explicitly specified, and is dependant on the implementation of registerMessageDelivery and resetStatistics in order to allow more flexibility.

JMX Interface

The Qpid JMX interface level that supports statistics is 1.9. Each object (MBean) that can generate statistics will add the following attributes and operations:

The following MBeans have had statistics attributes added:

• ServerInformation
  The entire broker, statistics for all virtualhosts. The totals for the broker will be equal to the sum of the totals for all virtualhosts. Rates for the broker include messages from all virtualhosts, so the broker peak can be higher than individual virtualhosts, and possibly also higher than the sum, due to slight timing differences. This is to be expected.
  org.apache.qpid:type=ServerInformation,name=ServerInformation,*

• ManagedBroker
  This is just a misleadingly named virtualhost. Note that the sum of all connections statistics will not always equal the statistics for the virtualhost, as connection MBeans are discarded when the connection is closed.
  org.apache.qpid:type=VirtualHost.VirtualHostManager,VirtualHost=*,*

• ManagedConnection
  Individual connections, which can be selected on a per-virtualhost basis. The name of a connection is usually the Java toString() representation of the address of the remote internet socket making the connection, so it is usually not possible to determine these in advance. These allow enabling and disabling of statistics generation.
  org.apache.qpid:type=VirtualHost.Connection,VirtualHost=*,name=*

The JMX attributes that record statistics are always present, and will have a value of 0/0.0 if generation is not enabled, and the statisticsEnabled attribute will be set to false.

Usage

The JMX JConsole application can be used to view the attributes, both as discrete values or as graphs. Sample output is shown below, illustrating the virtualhost statistics for a broker with a producer and a consumer attached and sending messsages.

Unable to render embedded object: File (jconsole-statistics-zero.png) not found.
Virtualhost statistics attributes at broker startup

Unable to render embedded object: File (jconsole-statistics-graphs.png) not found.
Virtualhost statistics graphs and attributes after sending and receiving messages through the broker

Testing

One caveat related to testing is that these statistics, apart from totals, are by their nature time dependent, and subject to race conditions, where sending messages as part of a test can overlap two sample periods, instead of one, causing seemingly incorrect results.

Unit

The StatisticsCounter class is suitable for unit testing. Tests checking class creation and operation check the total, rate and peak data, as well as other class properties. It is difficult to write a test to provably show thread safety when updating the counter with new events, but there are tests to check that out-of-order events will not cause problems with the data generated.

System

System testing covers the generation of statistics using a running broker, as well as the configuration mechanisms and the operation of the JMX interface to the data and the operational logging output. The following system tests have been written, all using a shared parent test case class, MessageStatisticsTestCase which sets up the JMX connection to the broker.

• MessageStatisticsTest
• MessageStatisticsDeliveryTest
• MessageStatisticsReportingTest
• MessageConnectionStatisticsTest
• MessageStatisticsConfigurationTest

These tests can be run with the following command, from the systests module directory:
$ ant test -Dtest=Message*Statistics*Test

Performance

To measure performance, a release of 2.6.0.7 was generated, using the standard release mechanism. The data should be compared with the previous [results] for the 2.6.0.6 release. The performance test suite was run on noc-qpiddev02.jpmorganchase.com with the broker running on noc-qpiddev01.jpmorganchase.com. Statistics were enabled on the broker by editing the etc/persistent_config.xml file to set statistics generation to true for the broker, virtualhosts and connections, as well as to report every hour (without resetting the statistics). The Disabled configuration used the provided default configuration file, and the Broker Only configuration used the same as the first set of tests, but with the //statistics/generation/virtualhosts and //statistics/generation/connections elements set to false.

The following command was executed for each of the configurations, and the results are aggregated into the tables below:
$ ./Throughput.sh

Initial Results

These results use the code from SVN revision r1033077, annd were generated on the 09 and 10 November 2010.

Throughput Numbers

There was no obvious difference between broker only and all statistics, so that testing was discontinued.

Comparison with previous release:

Analysis

Further testing with different combinations of broker, virtualhost and connection statistics enabled will need to be carried out to determine where the greatest penalty in performance lies. Based on this, there may be changes required to the StatisticsCounter class, or the propagation mechanism that links child and parent counter objects.

It is also important to determine what the maximum acceptable loss of throughput is to a customer. It would seem desirable to have less that 5% decreate in throughput due to statistics generation, however it should be noted that a performance penalty is inevitable when adding code to the message delivery and receipt paths in the broker, and the aim is only to minimise this, not to eliminate it.

Further Testing

The 7% performance loss was felt to be unacceptable, so modifications were made to the StatisticsCounter code to reduce the time spend carrying out computations. The following changes were made:

1. The system property qpid.statistics.samplePeriod was changed from 1000 to 2000 and 5000.
2. The code in StatisticsCounter was modified to defer more calculation to the end of a sample period.

Throughput Numbers

The same 2.6.0.7 broker with QPID_OPTS set to -Dqpid.statistics.samplePeriod=N where N is 2000 or 5000.

Old is an unmodified 2.6.0.7 broker, the new broker has QPID_OPTS set to -Dqpid.statistics.samplePeriod=5000 and some changes to the StatisticsCounter class that move computation to the end of the sample period, all three have QPID_JAVA_MEM set to -Xmx2g. Results are the average of three runs.

More Tests

Two 5 minute runs of a simple test, producing and consuming messages as fast as possible in a single thread. This was run on a HP DL585, Quad dual-core 2.2GHz Opteron, 8Gb, hence the difference in reported rates.

• Statistics Configuration Enabled
  $ QPID_OPTS=-Dqpid.statistics.samplePeriod=2500 QPID_JAVA_MEM=-Xmx4g ./qpid-server
  3792.9 msgs/s
• Statistics Configuration Enabled
  $ QPID_OPTS=-Dqpid.statistics.samplePeriod=500 QPID_JAVA_MEM=-Xmx4g ./qpid-server
  3961.8 msgs/s
• Statistics Configuration Enabled
  $ QPID_OPTS=-Dqpid.statistics.samplePeriod=30000 QPID_JAVA_MEM=-Xmx4g ./qpid-server
  3999.3 msgs/s
• Statistics Configuration Enabled
  $ QPID_OPTS=-Dqpid.statistics.disable=true QPID_JAVA_MEM=-Xmx4g ./qpid-server
  4156.3 msgs/s
• Stock Apache 0.5 Download - http://apache.mirror.anlx.net//qpid/0.5/qpid-java-broker-0.5.tar.gz
  $ QPID_JAVA_MEM=-Xmx4g ./qpid-server
  4068.3 msgs/s

Profiling

To properly determine hot-spots in the code, a profiling run was made using the YourKit profiler. The simple test used in the previous section was run with the profiler attached, and CPU statistics were collated. The profiler detected the following hotspots:

• StatisticsCounter.registerEvent - 4%
• AtomicLong.addAndGet - 3%
• AtomicLong.compareAndSet - 2%

Since the AtomicLong calls are made inside registerEvent, it seems that this is where the CPU is spending the extra time that is causing the slowdown. In order to mitigate this, the registerEvent method was changed to be synchronized and the internal logic changed to use primitive long types and standard arithmentic operations. After this change, the profiler no longer showed the registerEvent as a hotspot in the code when another test run was made.

The updated code was copied to the broker being used for throughput testing, and the TTBT-NA-Qpid-01 test was re-run, with results shown below (again, an average of three runs was taken).

Finally, the single-threaded test was also run against 2.6.0.6 and the latest 2.6.0.7 build, with the following results:

In order to more fully test this, the script which starts the TTBT-NA test, and the Throughput.sh sctipt itself, were copied, and modified. A series of scripts, STAT-XX.sh, was created, consisting of identical calls to the TTBT-NA test apart from the number of consumers, which varied from 01 to 16 and is represented by XX, and a Statistics.sh script was created which calls each of these in turn.

The STAT throughput tests were run against a standard 2.6.0.6 broker and the 2.6.0.7 build with all statistics generation enabled. It is expected that the difference in throughput should increase as the number of consumers increases. Note that these tests were only run once so are not as accurate as the averaged, multi-run datasets.

2.6.0.6 Throughput Numbers

$ QPID_JAVA_MEM=-Xmx2g ./qpid-server -c ../etc/persistent_config.xml

2.6.0.7 Throughput Numbers

$ QPID_OPTS=-Dqpid.statistics.samplePeriod=5000 QPID_JAVA_MEM=-Xmx2g ./qpid-server -c ../etc/persistent_config.xml

Although it is difficult to draw any real or meaningful conclusions from these results, note that single consumer performance degradation is negligible.

A useful further test would be to run the 2.6.0.7 broker with only connection-level statistics being generated? This ought to remove the contention for the lock on the counters for virtualhosts and the broker when many consumers are being delivered to.

2.6.0.7 Throughput Numbers

$ QPID_OPTS=-Dqpid.statistics.samplePeriod=5000 QPID_JAVA_MEM=-Xmx2g ./qpid-server -c ../etc/connection_config.xml

Conclusion?

It would appear that there is a penalty of a few percent (up to 4%) for a single thread, rising to over 10% when there are many threads. Further testing will be required to determine how the number of connections (i.e. threads) causes the performance to vary. This is, of course, hampered by the fact that the throughput tests exhibit up to 4% variability between the minimum and maximum results for a particular test.

Additionally, it is unclear which of the two mechanisms (AtomicLong versus synchronized registerEvent method) used in the counter is preferable. For the many-threaded, multi-consumer/producer case the AtomicLong seems the better choice, for a single producer/consumer the synchronized registerEvent method is better.

Another point to note is that the actual per-message latency increase is quite small, and it is only when sending large numbers of messages using many connections that the degradation comes into play, and the ratio of messages to data is small, i.e. the data throughput does not concern us, it is purely the number of messages. This means that for most applications there should not be a noticeable difference in performance, with any small change in per message latency being eaten up in noise.

Another point to note is that in these test garbage collection

Further Modifications

This data was generated after modifying the broker code to place statistics recording for message delivery after the message is enqueued at the broker (or at least, after an attempt has been made to do so).

As a cross-check, the tests were repeated using a stock 2.6.0.6 broker, then again (twice actually), with the 2.6.0.7 broker, like the first time, in case there are any environmental factors that are skewing the results. And finally, with the 2.6.0.7 broker, but with statisatics generation disabled.

These results show that the persistent testing has results that are about the same for both versions, whether the statistics are enbled or disabled. This is due to the naturally lower throughput causing less contention and allowing the statistics generation to run unimpeded. The transient tests get worse with statistics generation enabled, due to the much higher message throughput and the fact that may messages are trying to update the counters at the same time.

Latencey

As a general recommendation, I would suggest that statistics generation is only enabled in cases of low message (count, not size) traffic, where the broker is not being 100% ustilised in terms of CPU. Persistant messaging is nescessarily I/O bound, interms of disk access, and this is usually the determining factor in message latency, so adding the statistics counters places no large additional burden, and will not add a large amount to the latency, certainly less that 5% degradation. It is obvious that any additional processing that talkes place during the act of delivery or receipt of a message will inevitably add latency and decrease throughput on the broker. If a broker is already operati ng at peak performance, something that is only possible with transient messages, which are only dependant on the amount of CPU and RAM available, then the enabling of statistics counters will have a greater effect, possibly degrading pewrformance by over 10%.

Tasks

• Create generic data capture utility for gathering stats on received/delivered messages inc current/peak messages/sec and rolling total messages inc message count and bytes (payload only) stats, inc unit tests. Requires further discussion.
• Configure stats capture (on/off) for broker (config.xml - new section) and per connection (jmx) and data extract dump interval, and code to dump stats data
• Expose stats via JMX MBean attributes for query by users (notification - reqs to be confirmed with client), add reset feature via JMX and tests for these features. JMX changes to expose new stats attributes and reset function, inc tests
• Performance test to measure overhead of stats calculation (see RG email/example class) - separate from perf test harness, small class to measure calc cost only

QPID-2932 Add statistics generation for broker message delivery
QPID-???? Port to trunk