Category: OpenTelemetry

MQ, JMS and Opentelemetry

I wanted to use Opentelemetry with MQ. One option is to use JMS, and the “code free” Otel support.

This code-free-support intercepts the send and receive methods, intercepts them, and sets up the Otel support (in MQ).

See here for information on the Java Otel instrumentation.

My code

I used the IBM MQ sample JMS programs JMSProducer and JMSConsumer.

export CLASSPATH=/opt/mqm/java/lib/com.ibm.mq.allclient.jar:$CLASSPATH
export CLASSPATH=/opt/mqm/samp/jms/samples:$CLASSPATH
export CLASSPATH=/home/colin/Downloads/opentelemetry-javaagent.jar:$CLASSPATH
export OTEL_JAVAAGENT_ENABLED=true
export OTEL_JAVAAGENT_LOGGING=simple
export OTEL_EXPORTER_OTLP_PROTOCOL=grpc
export OTEL_EXPORTER_OTLP_ENDPOINT=http://10.1.0.2:4317

java -javaagent:/home/colin/Downloads/opentelemetry-javaagent.jar
-Dotel.resource.attributes=service.name=ColinsJMS
-Dotel.traces.exporter=console
/opt/mqm/samp/jms/samples/JmsProducer.java \
-m MQPA -d RSERVER -l SYSTEM.DEF.SVRCONN -h 172.26.1.2 -p 2414

This produced

Jaeger output

Which shows the message passed through MQ and was got (by the server program).

Because the sample JMS program does not allow you to specify a ReplyToQueue manager name, the server cannot send the reply back.

I changed the JMSProducer to specify a replyToQueue, and pass this as part of the message.
I used the JMSConsumer program unchanged.

The updated application

export CLASSPATH=/opt/mqm/samp/jms/samples:$CLASSPATH
export CLASSPATH=/home/colin/Downloads/opentelemetry-javaagent.jar:$CLASSPATH
export OTEL_JAVAAGENT_ENABLED=true
 # export OTEL_JAVAAGENT_LOGGING=simple # default
export OTEL_EXPORTER_OTLP_PROTOCOL=grpc
export OTEL_LOGS_EXPORTER=console
export OTEL_METRICS_EXPORTER=console
export OTEL_EXPORTER_OTLP_ENDPOINT=http://10.1.0.2:4317	
java -javaagent:/home/colin/Downloads/opentelemetry-javaagent.jar \
     -Dotel.resource.attributes=service.name=ColinsJMSProducer \
     -Dotel.traces.exporter=console \
     /opt/mqm/samp/jms/samples/colinProducer.java   \
-m MQPA -d RSERVER -l SYSTEM.DEF.SVRCONN -h  172.26.1.2 -p 2414 -r CCOLIN

echo "===================================================="

java -javaagent:/home/colin/Downloads/opentelemetry-javaagent.jar \
     -Dotel.resource.attributes=service.name=ColinsJMSConsumer \
     -Dotel.traces.exporter=console \
     /opt/mqm/samp/jms/samples/JmsConsumer.java \
    -m MQPA -d CCOLIN -l SYSTEM.DEF.SVRCONN -h  172.26.1.2 -p 2414

When this ran, the Otel data displayed in Jaeger was

Comments on the output.

  • The chart shows
    • A message is put to an MQ remote queue called RSERVER on queue manager MQPA. This operation takes 20.2 milliseconds.
    • The message is got from a queue called CSQ9 (a transmission queue). This flows over the network to queue manager CSQ9.
    • The message is put to a queue CSERVER on queue manager CSQ9.
    • An application on CSQ9 gets the message, does some processing and puts a reply to queue CCOLIN ( on queue manager MQPA). You cannot see this program in the trace.
    • The mover on CSQ9 gets the message from the transmission queue YMQPA and sends it over the network
    • The mover on CSQ9 puts the message to queue CCOLIN
    • The above processing is very quick.
    • The putting JMS program ends, and starts the JMSConsumer program.
    • 3.2 seconds after the initial put, the JMSConsumer program gets the message (and the MQGET takes 3.6 ms). The start of the second Java program takes a long time (most of this 3.2 seconds)
  • There are no entries for the JMS programs themselves. There are only entries for the MQ on z/OS.
  • Although there were two JMS Java programs involved – the Jaeger output just shows the MQ processing

What next?

Although this has shown that you can easily add Otel processing to your JMS program, the output is lacking.

You can manually instrument your Java program, as described by the Opentelemetry documentation.

Opentelemetry: Jaeger handling clock mismatches

I am collecting Opentelemetry data from z/OS and Linux, unfortunately the clocks on the two systems are not synchronised.

When I display the data in Jaeger, instead of looking like

Where the transaction took 56.5 milliseconds, the output looks like it took over 26 seconds.

The z/OS data (MQPA and CSQ9) is all squashed to the right because the z/OS clock is out by about 26 seconds.

How to fix it

Within the Jaeger yaml configuration file you can specify

extensions:
   jaeger_query:
     max_clock_skew_adjust: 30s

This says if it looks like the data has a time skew, and the time is off by less than 30 seconds, then make the timings look sensible.

How does it work?

The Opentelemetry data has information about each span processed. One of the fields is the parent span.

If Jaeger know know that the parent span executed between 13:00:00 and 13:00:01, and the spans from z/OS were for times 13:00:20 to 13:00:21, it looks like the z/OS times are out by 20 seconds, and so Jaeger can compensate for this.

By default max_clock_skew_adjust is 0, so there is no compensation.

Processing Opentelemetry data – what’s missing (or is hard)

I’ve spent several weeks implementing Opentelemetry, and although it works, I feel there are bits missing, rather than “wow, what a perfect solution”. I tried to put myself in the position of supporting an enterprise customer who has many critical business applications, across many systems and platforms. The customer wants to be able to identify problems, before their end users notice, and before the end users flood social media with complaints.

Below are my thoughts on what I have learned. I may be totally wrong; maybe I didn’t know about some facilities which would solve the problems. If you know differently – please tell me. I love getting feedback – and I will update the documents.

I want to see the business view not the detailed plumbing view

Problem:

I’ve been to visit customers, and been allowed to visit their “mission control”. This is like the mission control for a moon landing. There are perhaps 200 screens showing all aspects of the business from the application throughput, through to the temperature of the water in the cooling systems. A screen can be selected and displayed “full screen” so every one can see it.

How I see the Opentelemetry data.

By default the information reported in Opentelemetry dashboards shows the plumbing; This database table, that CICS transaction, this MQ queue.

The business wants to know about “online banking”, or a function like “credit user’s account”, and not the name of a CICS transaction. Some services are common to all business applications, such as logon, and move_money. Some services are business application specific, such as “ATM statistics”.

One solution

An input stream of OTEL information can be fanned out to multiple streams. You might have one stream for “Enterprise monitoring”, and another stream for “CICS monitoring”, or “MQ monitoring.

The Opentelemetry collector can fan out the data to a CICS Grafana, an MQ grafana, and a z/OS grafana. Each of these grafanas has been configured to provide the information that the CICS, MQ, and z/OS people need to see.

The Opentelemetry collect can transform the input data, from “MQGET COLIN” to the name of a business application.

- set(span.name,"Payroll MQPA app gets the reply") where span.name == "MQGET COLIN"
- set(span.name,"Creditcheck application GET")     where span.name == "MQGET CSERVER"

A different approach

When displaying data in Prometheus or Grafana, you can select which data is included in the displays.

For example if you have specified tracestate when you created your OTEL data, you could have one window for when w3.tracestate=”APPL=MYAPPL”, and another window with w3.tracestate=”APPL=ONLINE BANKING”.

Half the information is not available

Problem.

The aim of the Opentelementry is to identify where work is being delayed, and why. However it only reports on how long a piece of work took.

For any work request there are two components

  • The transaction is doing something, reading a file, sending a request etc
  • Waiting for something. This could be the response to a request. The work could be waiting, for example, because of insufficient resources (the CPU is too busy), or there is a long network round trip time.

The Opentelementry dashboard only reports on when something is being done (a database update has been done). It does not report on the waiting. Often the waiting is the longest part of a transaction. As a result the dashboard is not reporting all the facts.

If you consider the simplest application where an application queues some work, and the work executes at a later date. For example a CICS transaction schedules another CICS transaction in another CICS region on a different LPAR in the sysplex. The started transaction may be delayed because too many other requests are queued up.

The business transaction is:

  • Run a CICS transaction ABCD – which issue a START of transaction WXYZ. The whole transaction takes 1 millisecond elapsed time.
  • There is some delay due to getting the request to the remote system, and a delay until the transaction can run
  • After 10 milliseconds, transaction WXYX runs, which takes 1 millisecond.

The dashboards will report

  • Transaction ABCD 1ms
  • Transaction WXYZ 1m

So shows the business transaction taking 2 ms.

It does not always show the 10 ms delay before the work was scheduled. (it depends on what data is generated)

  • If the time before transaction WXYZ increases to 20ms – the dashboards do not show it.
  • If the transaction ABCD takes longer (perhaps it had a longer database request), then it would show up.

Answer:

I wrote some Python code which creates a new Opentelemetry record covering the gap between two records, so from the start of transaction WXYZ back to the end of its parent. This gave me three records in my dashboard

  • Transaction ABCD 1ms
  • Delay before transaction WXYZ starts 10 ms
  • Transaction WXYZ 1m

This could be done properly by writing a processing stage in GO in Opentelemetry.

There is too much information

Problem: Too many layers in the cake

In simplest typical MQ transaction, I have 8 items displayed on the dashboard

  • Client application puts a message to a queue
  • The mover gets the message and sends it to the remote system
  • The mover on the remote system puts the message to the queue
  • The server application gets the message
  • The server puts the reply
  • …

On the dashboard it shows the average time for each of these, but it is hard to tell which colour is for which action.

Answer:

You can say display the top n values. ( I used 4). If something takes longer than usual, it will appear in the list – and so the list will have a new colour – and you can see something is different.

Problem: you are using too many values

Each data record has a value (such as duration) and “dimension” (or attributes) of the record, such as Originating system, Opentelemetry instance, Span-name(such as transaction ABCD).

By default if you display the data, there will be a “layer” in the cake for every unique combination of dimensions.

If you have 50 different CICS transactions, you will have 50 slices. You can select which attributes to select by, and can group them by regular expression.

The problem is if the span is called “CHECK USERID xxxxxxx ” or MQPUT CSQX……” where there is a span for each userid checked, and for every MQ dynamic queue. The number of these depends on activity. It is hard to display the data so you can get useful data out of it.

Answer:

In the Opentelemetry collector you can use a transformation to set(or add) a value depending on the contents of a field. The following checks the name of an MQ Queue. If the queue name starts CSQX. then consider it a dynamic queue and give these entries the generic name CSQX*

set(span.name,"MQPUT *CSQX") where Substring(attributes["span,name], 0, 11) = "MQPUT CSQX."

See Understanding the OpenTelemetry Transform Language

The statement would replace all span names starting with MQPUT CSQX. with the string MQPUT *CSQX, and so be obvious this is a substituted name.

Drilling down on outliers

When a problem occurs (the duration of the business transaction take much longer than usual), you want to be able to drill down, and find out why.

Problem: Drilling down to find the root cause is hard

Jaeger display

If you are using Jaeger display to display the business transaction response time, you may spot outliers, and be able to click on one, and see the profile of the data.

You cannot select a time range, only the last 5m, 15m, 1h etc. You may have millions of records in 1 hour, and I do not think Jaeger is up to it, because it suggests processing 20 records.

Grafana display

Grafana displays aggregated information, so does not have individual records. You can see the time interval when the long durations occurred.

Answer:

You can configure Grafana links. When you click on a data item, a pop up giving information about that point is displayed. You can configure links which can be selected. For example select the Jaeger display of this service, between the two time stamps selected.

This was not easy to set up – because the links did not display every time. When it works it works well.

You can configure links to pass a URL and parameters from the data, or take an action.

Start here for processing Opentelemetry data

I’ve spend a few weeks trying to generate and use Opentelemetry data. My salesman’s vision does not match the practice. Below is what I have learned from hands on. It shows the typical usage of displaying Opentelemetry data using Jaeger and Grafana. What I say may be wrong, if so please tell me and I’ll correct it.

There are follow-on posts

What is opentelemetry?

As work moves through a system it reports where it is. A central collector takes this data and can display where the work item spent its time.

This shows an application putting a message to an MQ queue, on queue manager MQPA, flowing through to a server on queue manager on CSQ9, and a response flowing back.

The overall transaction time was 71 ms.

The architecture

On z/OS the OTEL data is written to SMF. There is a Java application which runs on z/OS, which reads from SMF, and sends it to an Opentelemetry collector (running on my Linux laptop).

The Opentelemetry collector generates data in the form for “standard” packages Prometheus and Grafana to process, and display dashboards of the information.

There are two data models for sending data between components

  1. The Opentelemetry collector has a push model. The recipient is a web server, and the OTEL collector sends JSON data over a POST request to the HTTP server.
  2. Grafana has a pull model. It periodically sends a request to its providers saying “send me data on ….”

Prometheus has a database, which has a web server for capturing the data from the Opentelemetry client. Prometheus saves the timestamp data efficiently. Prometheus provides another web server to respond to the “send me data …” from Grafana.

Prometheus accepts metric data from sources like Opentelemetry, but it does not take the raw Opentelemetry “log” data directly into Prometheus – I think of Prometheus as a database.

Grafana takes data from many sources (such as Prometheus) and displays dash boards, which typically are time sequences of data. See below.

There is another component Jaeger, which converts the data from OTEL into data suitable for Grafana.

I expect people will use Grafana for overall monitoring, and Jaeger to dig down into a time range.

Note 1: You cannot go directly from Opentelemetry to Grafana, because Opentelemetry only provides a push model.
Note 2: You can write your own components to process the data from Opentelemetry.

Grafana

A typical chart showing where time was spent

There are many layer – each one is for a unique span name and dimensions (meta data). There is a pop up with information about where the graphical cursor is. The information shows for queue manager MQPA, the MQPUT to RSERVER took 0.635 milliseconds.

Overall the work took between 7 and 4 milliseconds.

You can display multiple charts in a dashboard

This shows the average times for the different spans ( MQGET COLIN), and the count of “transactions”.

The MQPUT to CSERVER was highest, and about 1.2 milliseconds.

For more information on Grafa see Start here for processing Opentelemetry data – visualisation in Grafana

Jaeger

Jaeger is a component which does two things

  • Visualises the data – see the image at the top of the blog post.
  • Can aggregates the data for Grafana to use

Visualise the data in Jaeger

By default it displays 20 entries

and

This shows there were two queue manager CSQ9 and MQPA, there were 8 spans (recorded data) the duration if each item, and the date. ( I think the date format is wrong .. you want hh:mm:ss – because you know what the day and date are!

If you click on the blue Trace Name or a blue dot – you get a detailed picture of where the time was spent

For more information on displaying data in Jaeger see Start here for processing Opentelemetry data – visualisation in Jaeger