sum (rate(traces_span_metrics_duration_milliseconds_bucket[1m]) ) by(le)
Select explain
and click the enable the query tree view. This gave me
The traces_span_metrics_duration_milliseconds_bucket returned 96 results.
Hovering over the traces_spans… line shows the unique values of the span_names, le:6, exported_job etc. The image shows the unique values of the span_name.
The rate calculation gave 96 results
The sum by(le) gave 6 results – matching the value in the hover over the traces_span_metrics_duration_milliseconds_bucket
You can click on a box to get an explanation of that box. For example the sum by(le) gave
The second part of the query
The sum returns one value.
The combining the two subqueries
The first part before the query gave 6 results, but the part after the ‘/’ gave 0 results, even though the sum() gave 1 result.
Further down was
This shows the data on the left is a time an array of multiple values (for each le value), but there is only one value on the right hand side, and this is used once. Because there is no value available for the coloured entries – they are dropped.
The problem
I have a vector with multiple elements, and I want to divide it by a vector with only one element. This does not work.
You can use the scalar function to covert a vector with one element to a scalar, and the calculation vector/scalar will work
sum (rate(traces_span_metrics_duration_milliseconds_bucket[1m]) ) by(le) / scalar(sum(rate(traces_span_metrics_duration_milliseconds_count[1m]) ) )
I had been using Prometheus to display Opentelemetry data from MQ on z/OS, but was having problems getting it to display what I wanted. I realised I did not understand how Prometheus stores and uses its data.
Prometheus handles time stamp data very well, “At this time, here are the metrics”. Prometheus provides the capability to display the data in many formats.
I found this course very clear and helpful. I did not read it end to end, but went to the topics of interest.
There is a discussion about metrics from Opentelemetry which you might wish to read after understanding the basics.
There are different sorts of data
Some numbers go up and down
The value of the depth of a queue can go up and down, and you are usually interested in the value at a certain time.
If you have the queue depth at the start of an interval, and at the end of the interval, you cannot take the average of the values. For example if the depth of the queue at midnight is 1000, and at one minute afterwards the queue is emptied, and stays empty till 1 AM, when it gets to depth 1000 – the “average” does not mean anything.
Some numbers just increase
An example of numbers that just increase, is the number of requests processed since the application started. The absolute number is not important, because the longer the application is active, the larger the number. The graph is just a line that goes up. You are more interested in questions like “how many requests happened in the last half hour”. This requires two values at different times.
With the requests, you might have the count of the requests, and also the sum of the duration of the requests. To find the average you calculate the sum/count. This is a true, but unhelpful statement.
If your application has been active for a week, calculating sum/count will give you the overall average. After midnight when there is no transaction activity, the average stays the same, non-zero value. This is a boring metric.
It is more interesting to take a time range, for example 1 minute, and calculate the sum of the durations of records in this hour/count of records in this minute. Then at the end of every minute, display the average value for the preceding minute. Interesting charts include
The number of requests in the last minute
The average response time during the last minute.
The key lesson when using these ever increasing values, is you take two time stamps and do calculations on the differences between the the two times.
Instance data and range data
Prometheus has two “types” of data. Instance value where there is one time stamp involved (what is the value at this time?), and Range values where more than one timestamp is involved, for example the increase of a value between two timestamps.
Some functions need a scalar (instance) value, other functions need a range value of two timestamps.
With some functions, I kept using Instance value data – when I should have been using Range values. So I wrote this blog post to help me understand the data model.
Data has attributes
A data item has information
The label, such as count_of_requests, or sum_of_durations
Value, this could be a integer, or a string (“OK”)
A timestamp
Attributes. Prometheus calls these dimensions, other products call these, tags or meta-data. These should be enough to identify the source, and attributes about the source which might be interesting in analysis or reports.
Example data
Below is some example data
Label
Timestamp
Value
Attributes.
total_count_requests
… 19:30:04.123456
6000
{jobname=”MYJOB”, request=”database”}
total_count_requests
… 20:00:00.987654
7000
{jobname=”MYJOB”, request=”database”}
total_duration_requests
… 19:30:04.123456
90000
{jobname=”MYJOB”, request=”database”}
total_duration_requests
… 20:00:00.987654
95000
{jobname=”MYJOB”, request=”database”}
total_count_requests
… 19:30:04.123456
400
{jobname=”MYJOB”, request=”webserver”}
total_duration_requests
… 19:30:04.123456
4000
{jobname=”MYJOB”, request=”webserver”}
total_count_requests
… 19:45:04.123456
200
{server=”MYSERVER”}
total_duration_requests
… 19:45:04.123456
2000
{server=”MYSERVER”}
There are metrics with labels total_count_requests and total_duration_requests.
The labels can refer to different applications, such as jobname=MYJOB, and server=MYSERVER
For jobname=MYJOB, there are requests=database, and data=webserver.
Focusing on the data you want
If you display “total_count_requests”, you will get a graph showing the data for all total_count_requests data, including both jobname=”MYJOB” and server=”MYSERVER”
You can use
total_count_requests{jobname="MYJOB"}
This will display only the total count requests where jobname=”MYJOB”. In the chart you will get a layer for each unique combination of attributes, so a layer for requests=”database” and a layer for requests=”webserver”.
I am working with metrics traces_span_metrics_duration_milliseconds_sum, and traces_span_metrics_duration_milliseconds_count. I’ll shorten these to _sum and _count.
If you have two data values, count of requests, and duration of requests, you can calculate the average time per requests: _sum/_count. If these values are cumulative, that is they are not reset periodically, then you need to be careful how you interpret the data. The average value will be the average value of all requests. Overnight when there are no requests being processed, the average value remains constant.
What people are more interested in is the change between two points in time, and calculating the average.
You can aggregate the data such as _sum[1m] and _count[1m] which returns the sum of the data values in the 1 minute interval.
If _sum[1m] has range values [20,40,60], and _count[1m] has range values [1,2,5] then _sum[1m] / _count[1m] is iterate over the value, _sum[i]/_count[i], which produces [20,20,12]
You can use the increase function which takes two sets of timestamp records.
This is computed as ((delta(_sum)/1m) /((delta(_count)/1m) – the time interval cancels out to give delta(_sum)/delta(_count) which is the same as increase(…)/increase(…).
Displaying the sum(increase….)/sum(…) in Grafana, you can use explain query – and it gave
Fetch all series matching metric name and label filters.
increase(<expr>[1m])
Calculates the increase in the time series in the range vector. Breaks in monotonicity (such as counter resets due to target restarts) are automatically adjusted for. The increase is extrapolated to cover the full time range as specified in the range vector selector, so that it is possible to get a non-integer result even if a counter increases only by integer increments.
sum(<expr>)
Calculates sum over the dimensions.
The basic data point
A data point has
a metric name, such as “requestActiveTime”, “traceCount”, “traceSum”
a timestamp – of when the data point was created
a value – depending on the metric, it could be a string, a counter (which only increases), or a numeric value (which can go up and down)
dimensions/tags/attributes/labels. Zero or more meta data keyword=values pairs, such as “jobName=MYJOB”, “activity=database”
The smallest database
time t0
time t1
time t2
requestCount (task=”job1″)
5
6
7
requestCount (task=”job2″)
7
9
10
requestSum (task=”job1″)
24
30
25
requestSum(task=”job2″
30
50
60
Displaying data
Display all data
If you display requestCount in Prometheus
requestCount
you will get 3 data pairs: (time t0, 5+7), (time t1,6+9), (time t2,7+10). This is the data displayed for all requestCount records at that timestamp added together. Prometheus can display the data in a table, or in a graph.
Tools like Prometheus and Grafana, select a window of data, so you can select the last 5 minutes, the last hour, or specify a date-time range.
You can request a subset of information
You can select which rows you want
requestCount{task="job1"}
You will get 3 pairs of data items: (time t0,5), (time t1,6), (time t2,7) This is all of the rows for requestCount with task=”job1″ (in the current selected time range).
If you refresh the display, the data will gradually move left and fall off the screen, as the time stamps fall out of the current display window.
You can display groups of data
by (task) (requestCount)
Will produce 6 pairs of data times
Job1: (time t0,5), (time t1,6), (time t2,7)
job2: (time t0,7), (time t1,9), (time t2,10)
Applying functions
You can use
sum(requestCount) sum by (task) (requestCount)
Instant values and range values
The data pairs above are called instance values – values from that particular instant in time. Some functions act on a range of time stamps. You can specify a timestamp range by specifying [5m] after the metric name, for a 5 minute range.
rate(requestCount{task="job1"}[5m])
with
time t0
time t1
time t2
requestCount (task=”job1″)
5
6
7
Where the above rate statement is the Per-second rate of increase, averaged over last 5 minutes. With rate() you pass in a time duration which covers a range of timestamps. Prometheus will process the data to match what you specify.
rate(v range-vector) calculates the per-second average rate of increase of the time series in the range vector.
More complex data
You might have some data points with multiple dimensions “jobname=…” and “userid=…”. Prometheus will output a record for every unique set of dimensions.
You can use
by(task) (jobrequestCount)
will produce records for each unique task – and ignore any other dimensions.
You can explicitly ignore dimensions
without(userid) (jobrequestCount)
if there were many dimensions, only the userid dimension would be excluded from the displays.
You can do calculations on time ranges
You can do
requestSum/requestCount
or
requestSum[1m]/requestCount[1m]
The requestSum[1m]/requestCount[1m] produces an array where the timestamp increases every minute.
Handing lots of data
There may be many thousands of OTEL records produced a second, from one system. Keeping this data for many months means there could be a lot of data to be stored, and would lead to expensive processing at display time.
Data can be aggregated
A simple aggregation is for the front end OTEL records processing system, to produce every 30 seconds (for example) one record with the sum, and the count of records. This means you get one record every 30 seconds – compare to 10,000 individual records.
This may not provide the right level of information. A better way is the use of buckets, where each record is accumulated.
This has a range of buckets 0 ms to 0.1 ms, 0.1 to 1, 1 to 2 … and how many elements were in that bucket
You can plot the data and get a “profile” like
If the profile changes significantly over time, then you need to investigate why.
What 5 spans had longest time?
I found the data displayed had 20 layers in the graph – too many to be able to see and manage. When investigating problems, you are interested in the long times – and can ignore the small times. You can use the display the top k values using the topk function.
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."
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.
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.
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
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.
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.
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
