With Opentelemetry, as work flows through a system, it sends “I am here” data back to a collector, which can process it, and pass it on to other tools to display the information on graphical dashboards.
I spent several days trying to work out why I was not getting any telemetry data from my queue managers.
Basic setup
Check SMF
The telemetry data is written to SMF. You should check it is being collected. The command D SMF gives output like
IFA714I 08.45.27 SMF STATUS FRAME LAST F E SYS=VS01 LOGSTREAM NAME BUFFERS STATUS A-IFASMF.DEFAULT 0 CONNECTED A-IFASMF.COLIN 0 CONNECTED A-IFASMF.INMEM 1289792 IN-MEMORY A-IFASMF.MQOTEL 393304 IN-MEMORY A-IFASMF.T1159 0 IN-MEMORY
This has some data in the buffers, so it looks like data is being produced.
You can check the SMF option using the command D SMF,O
This shows the MQ SMF records, type 1158 are mapped to name IFASMF.MQOTEL. It may be different on your system.
Check the data gatherer is active
This is a Java program which runs on z/OS and writes to an HTTP connection. I run mine as a started task.
This program does not report any statistics, if it is using CPU, then is may be processing records.
Check the network traffic
I use TLS encryption on my connection to the Opentelemetry collector server running on Linux. Using tools like wireshark on the connection allow you to see the overall traffic, but not the content of the traffic. For example
Shows there is traffic to and from port 4317 on my Linxu box.
The records with length of 8258 contains my Otel traffic
There is also TCP/IP Keep Alive flows every 15 seconds or so.
On the Linux Opentelemetry collector
During setup, I had the collector write to debug, and to a file, so I could see the traffic coming down.
But no data is being produced.
There are two switches that need to be enabled.
The Opentelemetry state is sent as a message property within MQ messages. There is a property traceparent, which identifies the high level piece of work. The data is of the format
trace identifier ‘-‘ span identifier ‘-‘ flags
Where flags is a two byte character string such as 01.
Format of the flags
If the rightmost bit of the flags is 0, then this signals do not collect any data.
If the rightmost bit of the flags is 1, then do more checks.
If the queue has an attribute OTELTRAC(ON) (either directly, or as specified at the QMGR level), then emit the otel data
Else do nothing.
The flag in the traceparent is called SAMPLED, which I found confusing. I didn’t want to sample – I wanted OTEL information for all records!
I had the flags specified as 00 and did not get any output. When I changed it to 01 I got the OTEL data – it was as easy as that.
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.
There is documentation on the internet explaining how to save (share) dashboards. It goes like “from the hamburger icon select share dashboard”. I do not have the hamburger icon. I think this is because I am using the free opensource version.
for uid in $(curl -u admin:password http://localhost:3000/api/search?query= | jq --raw-output '.[].uid') ; do echo $uid curl -u admin:panthe0n "http://localhost:3000/api/dashboards/uid/$uid" > "dashboards/$uid.json" done
The output was a JSON file. I do not think you can import it back into Grafana (because it says it does not have a matching schema), but at least you can see what the contents were, and manually add them back into Grafana.
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.
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 was recently asked, what is the simplest configuration of certificates on z/OS to get MQ AMS working. This took me a little while to get working, so I thought it was worth documenting. To understand how to configure AMS you need to have a superficial view of what happens under the covers.
You can have all userid use the same certificate. People in one department could all use the same certificate, which make implementing AMS much easier. You only need one recipient certificate for the team, and not have to manage people joining and leaving the team – which causes a head ache on the systems that send your system messages.
3 Create a signed user certificate with RSA, and keyusage to include DATAENCRYPT.
4 , 5 Connect this certificate to all users. Make it the default certificate
4 , 5 Connect this certificate to all users Connect the CA for this certificate to each user’s keyring.
6 Give each userid UPDATE access to their keyring.
For the queue manager
1 Create a keyring for the AMS started task userid.
2 Connect to the keyring, the certificates of all recipients on this queue manager
3 Connect to the keyring, all CA certificates for userids on the system, and the CAs for user on other platforms.
Refresh the AMS system. f xxxxamsm,refresh.
Simple, what could go wrong?
The longer answer – with explanations
With AMS, you can have
Message integrity. The message is visible in clear text, but you can be confident it has not changed since it was created
Message privacy. The message is encrypted. The message can only be read by people who have access to the private key of one of the specified recipients
Privacy and integrity.
Background
Public and private keys
With modern ciphers, you need a pair of keys. If you encrypt with one key you need its partner to decrypt. You pick one key, and make it available to every one, and this is called the public key. You keep the other one very secure, this is called the private key.
If you encipher something with the public key – then only someone with the private key can decrypt it
If I encrypt something with my private key. Anyone can decrypt it using my public key (you may ask why bother?), but the important bit is that because you had to use my public key – you know the message came from me! We have authentication.
A certificate has a public key in it.
Quick discussion on certificate authorities
You can have self signed certificates. You should not use them, because someone could change or replace it and you would never know.
You can have signed certificates. When you create a signed certificate it creates a checksum of the certificate, and encrypt this checksum with the Certificate Authority’s private key. This encrypted checksum becomes part of the certificate.
When you receive a signed certificate you do the same checksum (and store it temporarily) then you decrypt the encrypted checksum using the CA’s public key – and the two values should match. (This assumes you have the CA certificate.)
Your Certificate Authority certificate could have been created by someone else (The UK Certificate Authority ?), and goes through the same signing process.
The UK’s Certificate Authority certificate could have been signed by someone else… so we have a chain of Certificate Authorities.
The top level in the chain of CAs is self signed.
The players
There is the putter, the getter, and the queue manager. They each need their own key ring.
Message integrity
The message is visible in clear text, but you can be confident it has not changed since it was created.
Put the message
As part of the integrity function, it calculates a checksum of the contents of the message, and encrypts this with the user’s private key. What gets sent is
The original payload
The encrypted checksum
The putter’s certificate
The putter’s CA certificate.
The putter sets up a certificate called UserCert, signed by MyCA. This certificate has certain requirements – such as it must allow data encryption, and contain an RSA public key.
The putter’s keyring needs
the UserCert
This needs to be the default certificate.
If the certificate belongs to the putter’s userid, then it needs read access to the keyring
The UPDATE access says it can read the private key of a certificate which the userid does not own, READ access only gives you access to the public key.
For testing – give every userid UPDATE access to the keyring profile.
Get the message
When the message is got, the queue manager checks the certificate (+CA) in the message is valid, using the CA in the queue manager’s keyring. Then does the same logic as for signing a certificate.
Check the certificate in the message is valid (for example compare the CAs)
Use the public key from the certificate in the message to decrypt the checksum of the message
Do the same checksum calculation.
Compare the two answers. They should match if the message has not been tampered with.
The putter needs
the MyCA certificate.
The keyring is the same as for integrity.
The queue manager needs
The queue manager’s keyring needs the CA of the certificate in the message – so it can compare the it with the one in the message.
The queue manager’s userid needs only read access to its keyring. (Because it does not need access to any private keys.)
The getter needs
an empty keyring. (In practice AMS complains if the userid has an empty keyring because it fails to find the default certificate, so give it a certificate and make it the default).
Message privacy
The message is encrypted. The message can only be read by people who have access to the private key of one of the specified recipients.
With message privacy the following happens when the message is put:
An encryption key is generated using parameters from the putters certificate and the AMS configuration
The message is encrypted with this encryption key
From the MQ AMS definitions, there is a list of recipient’s Distinguished Names, such as CN=USER1,O=MEGACORP, and CN=USER2,OU=TEST,O=MEGACORP.
For each DN in the list, look in the queue manager’s keyring for the certificate with the distinguished name.
With the found certificate, use its public key to encrypt the encryption key
Build a list of [Distinguished_Name:encrypted encryption key, ….]
Send this list as part of the payload.
When the message is got, the getter
Extracts the getter’s DN from the getter’s default certificate
Scans the AMS data in the message for the list of [Distinguished_Name:encryption key, ….] for the matching DN
Uses the private key in the default certificate to decrypt the [Distinguished_Name:encryption key, ….], to get the message decryption key.
Use the message decryption key to decrypt the user’s message.
AMS setup
I am using a queue called AMS for my AMS testing. The AMS definitions were
To make the configuration easier (this is the simplest configuration, after all), the user certificate owned by ID(COLIN), and called LABEL(‘AMS’) is used by the getter userid below.
Queue manager keyring
The queue manager needs all CA certificates, and all the recipients certificates. When a recipient is specified, the queue manager’s keyring is searched for the certificate with the matching Distinguished Name. When it is found its public key is used. The private key is not used. The queue manager only requires READ access to the keyring, because it is not accessing private keys.
I used JCL to (re-)define my keyrings etc. This makes it easier to make one change, and repeat. It also means I can copy them to a different system and they still work.
RACDCERT LIST (LABEL('AMS')) ID(COLIN) RACDCERT LIST (LABEL('AMS2')) ID(START1) RACDCERT LIST (LABEL('NEW-CA')) CERTAUTH RACDCERT LIST (LABEL('NEW-CA2')) CERTAUTH
When using MQ AMS to encrypt MQ messages, it has been very frustrating to get messages like
CSQ0217E %MQPA CSQ0COPN Failed to process object ‘recipient public key certificate in recipient keyring’
and not know what the problem is. (Especially when the cause is recipient public key certificate is not in recipient keyring.
System SSL which provides all of the encryption has a trace capability. You enable it when you start AMS, so you have the overhead in normal operation.
It sometimes writes data to a file in Unix, other times you need to start GKSRVR and collect the CTRACE.
With AMS the trace data is written to a file in Unix. Use the unix gsktrace command to format it.
gsktrace gskssl.16777257.trc > gsk
Configuring the trace
In the AMS JCL procedure //ENVARS DD DSN=….,DISP=SHR
I have
####################################################################### # # GSKIT Trace # # If you are having problems with certificates and missing entries in # key stores you can enable GSKIT trace to help diagnose the problems. # # To enable/disable GSKIT trace, un-comment and update the following # environment variables as required. # # GSK_TRACE_FILE - Specifies the name of the trace file in Unix # System Services (USS). Insert the correct user # name and ensure you set the correct permissions # on the directories and files to allow the # user ID in use by IBM MQ for z/OS Advanced # Message Security to write the resulting trace # file. The current process identifier is included # as part of the trace file name when the name # contains a percent sign (%). The gsktrace command # can be entered in USS to format the trace: # # e.g. gsktrace gskssl.84017302.tr # # GSK_TRACE - Specifies a bit mask that enables System SSL trace # options to trace gsk_* calls. All trace options are # enabled if the bit mask is 0xff and all trace # options are disabled if the bit mask is 0x00.
GSK_TRACE_FILE=/tmp/gskssl.%.trc #SK_TRACE=0xff everything including payloads GSK_TRACE=0x0f just control stuff
If you specify GSK_TRACE=0xff you get a lot of data – including all the application data ( message content + any headers etc).
I found GSK_TRACE=0x0f provides what I need.
A first look at the data
There is data like
08/06/2026-07:00:49 Thd-0 ENTRY gsk_open_keyring(): ---> Keyring 'STCMQ/drq.ams.keyring' 08/06/2026-07:00:49 Thd-0 ENTRY crypto_generate_random_bytes(): ---> Length 20 08/06/2026-07:00:49 Thd-0 EXIT crypto_generate_random_bytes(): <--- Exit status 0x00000000 (0) 08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Record 'AMS' is the default key 08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Identifier 1 assigned to 'AMS' 08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate(): ---> 08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate(): <--- Exit status 0x00000000 (0) 08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Identifier 2 assigned to 'NEW-CA' 08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate(): ---> 08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate(): <--- Exit status 0x00000000 (0) 08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Identifier 3 assigned to 'DOCZOSCA' 08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate(): ---> 08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate(): <--- Exit status 0x00000000 (0) 08/06/2026-07:00:49 Thd-0 INFO gsk_open_keyring(): Identifier 4 assigned to 'AMS2' 08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate(): ---> 08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate(): <--- Exit status 0x00000000 (0) 08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate_extension(): ---> Decoding 08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate_extension(): <--- Exit status 08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate_extension(): ---> Decoding 08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate_extension(): <--- Exit status 08/06/2026-07:00:49 Thd-0 INFO gsk_build_issuer_chains(): Record 'NEW-CA' is issuer for ... 08/06/2026-07:00:49 Thd-0 INFO gsk_build_issuer_chains(): Record 'NEW-CA' is self-signed 08/06/2026-07:00:49 Thd-0 INFO gsk_build_issuer_chains(): Record 'DOCZOSCA' is self-signed 08/06/2026-07:00:49 Thd-0 ENTRY gsk_decode_certificate_extension(): ---> Decoding ... 08/06/2026-07:00:49 Thd-0 EXIT gsk_decode_certificate_extension(): <--- Exit status ... 08/06/2026-07:00:49 Thd-0 INFO gsk_build_issuer_chains(): No issuer found for record 'AMS2' 08/06/2026-07:00:49 Thd-0 EXIT gsk_open_keyring(): <--- Exit status 0x00000000 (0) Handle...
I ignore the date
I use the time to match the records to when the problem occurred. It is HH:MM:SS granularity
Thd-0, Thd-15. Work runs on AMS tasks. A task can run work for any userid. I’ve often found one thread does the processing for the putters and the getters. You have to guess when one piece of work ends, and the next starts.
ENTRY/EXIT/INFO this is the entry, exit, or just some information about the function
gsk_open_keyring() is the function. This is described in Cryptographic Services System Secure Sockets Layer Programming (SC14-7495-60) which I think is only available in PDF format.
EXIT gsk_open_keyring(): <— Exit status 0x00000000
Showing the function gsk_open_keyring(): worked successfully.
It shows the elements on the keyring
INFO gsk_open_keyring(): Record 'AMS' is the default key INFO gsk_open_keyring(): Identifier 1 assigned to 'AMS' INFO gsk_open_keyring(): Identifier 2 assigned to 'NEW-CA' INFO gsk_open_keyring(): Identifier 3 assigned to 'DOCZOSCA' INFO gsk_open_keyring(): Identifier 4 assigned to 'AMS2'
How do you find the problem?
You might have the time of day when the problem occurred. The trace is only HH:MM:SS, so there may be a lot of records.
I use ISPF edit.
X ALL
Find ‘Exit status’ all
exclude ‘Exit status 0x00000000’ all
This shows just the Exit status which are non zero. This should localise the problem.
Periodically it uses a new file – so check you are using the latest file.
Some records showing a problem
ENTRY gsk_validate_certificate(): ---> Data source count=1 ENTRY gsk_validate_certificate_mode(): ---> Data source count=1,... ENTRY cms_validate_certificate_mode_int(): ---> Data source count=1,... INFO cms_validate_certificate_mode_int(): validate root=566,... ENTRY gsk_name_to_dn(): ---> EXIT gsk_name_to_dn(): <--- Exit status 0x00000000 (0) DN: CN=START1,O=AMS,C=TEST INFO cms_validate_certificate_mode_int(): Validating CN=START1,O=AMS,C=TEST INFO cms_validate_certificate_mode_int(): No Signature Algorithm List Provided ENTRY gsk_decode_certificate_extension(): ---> Decoding certificate extension type 2 EXIT gsk_decode_certificate_extension(): <--- Exit status 0x00000000 (0) INFO get_issuer_certificate(): Using AuthorityKeyIdentifier to locate issuer ENTRY gsk_name_to_dn(): ---> EXIT gsk_name_to_dn(): <--- Exit status 0x00000000 (0) DN: CN=NEW-CA2,OU=TEST,O=COLIN INFO get_issuer_certificate(): Using issuer CN=NEW-CA2,OU=TEST,O=COLIN ENTRY gsk_get_record_by_subject_mode(): ---> Handle 275787C0 EXIT gsk_get_record_by_subject_mode(): <--- Exit status 0x0335300e (53817358) ERROR validate_certificate(): Unable to get issuer certificate: Error 0x03353024 ERROR validate_certificate_mode(): Unable to validate certificate: Error 0x03353024
This shows data is being processed from the message.
ENTRY gsk_name_to_dn(): —> shows data was passed in to routine to convert from the transmission (internal) format DN to a readable name
EXIT gsk_name_to_dn(): <— Exit status 0x00000000 (0) DN: CN=START1,O=AMS,C=TEST The output name is CN=START1,O=AMS,C=TEST
INFO get_issuer_certificate(): get the issuer name from the certificate
EXIT gsk_name_to_dn(): <— Exit status 0x00000000 (0) DN: CN=NEW-CA2,OU=TEST,O=COLIN this is the decoded issuer name
INFO get_issuer_certificate(): Using issuer CN=NEW-CA2,OU=TEST,O=COLIN look for the certificate with this DN in the keyring
EXIT gsk_get_record_by_subject_mode(): <— Exit status 0x0335300e It could not find the record in the keyring with the given subject DN.
Looking in the documentation gives 0335300E : Record not found.
There are many moving parts for AMS, and it is easy to get it wrong. The error messages produced often do not describe the problem.
This is a work in progress. If you have other problems, please let me know. I am expecting people to search with their symptoms, rather than read this document.
One day I’ll produce a list
reason 03353026; Failed to process object ‘pkcs7 enveloped data message.’; see ….
Bad key definition. User’s certificate has the wrong certificate type (such as Elliptic)
CSQ0215E %MQPA CSQ0CPUT Message protection failed, return code 00000008, reason 03353026 CSQ0217E %MQPA CSQ0CPUT Failed to process object ‘pkcs7 enveloped data message.’
From the GSK trace
ERROR gsk_make_enveloped_data_content_extended(): keyUsage does not allow key encipherment EXIT gsk_make_enveloped_data_content_extended(): <— Exit status 0x03353026 (53817382)
The key does not have Keyusage(dataencryption).
A key defined as NISTECC does not support data encryption. You have to use RSA or ICSF.
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.
