CPU performance is degraded on version 0.22.1

[osd42]

Hello
I spent days searching for CPU issue in my Dynatrace Python extension (which is basicaly a prometheus scraper for a Solace prometheus exporter).

I finally noticed a big performance gap between versions 0.21.1 and 0.22.1.

0.22.1 consumes 4 times more CPU than 0.21.1. I finally downgraded to 0.21.1 and my CPU is back to normal state.

Here is my usage:

 # Prometheus parser: https://prometheus.github.io/client_python/parser/
 for prometheus_line in utf8_lines:
 for family in text_string_to_metric_families(prometheus_line):
 for sample in family.samples:
 skip = False # By default, no metric is skipped unless we filter it

 if sample.name in wanted_solace_metrics:
 found_metrics += 1
 # self.logger.info("line: " + prometheus_line)
 # print("Name: {0} Labels: {1} Value: {2}".format(*sample))

 # NaN detection with math library
 if math.isnan(sample.value):
 invalid_metrics += 1
 self.logger.info("NaN value skipped " + sample.name)
 # If the value is NaN, we ignore it
 break
 else:
 valid_metrics += 1
 dims= {**sample[1], "node": nodename, "clustername": clustername}

 # Remove unwanted dimensions
 #define the keys to remove
 keys = ['client_name', 'client_address', 'client_profile', 'flow_id', 'acl_profile']
 for key in keys:
 result_pop=dims.pop(key, None)
 if sample.name not in censored_metrics_list and result_pop is not None:
 # print("DETECTED")
 censored_metrics_list.append(sample.name)

 # parse exporter errors
 if "error" in dims.keys():
 solace_prometheus_exporter_error=str(dims["error"]).replace('\"',"").strip()
 sanitized_solace_prometheus_exporter_error={ "error": solace_prometheus_exporter_error}
 dims.update(sanitized_solace_prometheus_exporter_error)

 # Remove unwanted queue protocols or modify queue names patterns
 if "queue_name" in dims.keys():
 # avoid the ingestion issue with bad queue names with trailing \n
 queue_name=str(dims["queue_name"]).strip()
 sanitized_queue_name = { "queue_name": queue_name }

 # update the queue_name in the dims payload
 dims.update(sanitized_queue_name)

 queue_name_lower=queue_name.lower()
 if queue_name_lower.startswith('#mqtt') or queue_name_lower.startswith('#cfgsync') or queue_name_lower.startswith('#p2p') or queue_name_lower.startswith('#pq') or queue_name_lower == "":
 # if queue_name_lower.startswith('#cfgsync') or queue_name_lower.startswith('#p2p') or queue_name_lower.startswith('#pq') or queue_name_lower == "":

 skip = True

 # Manage non skipped metrics
 if skip is False:
 # Keeps queue quota calcuted metrics
 if sample.name == "solace_queue_spool_usage_bytes":
 queue_usage.append({ "metric_name": sample.name, "md5_dims": hashlib.md5(str(dims).encode("utf-8")).hexdigest(), **dims, "METRICvalueMETRIC": sample.value})
 if sample.name == "solace_queue_spool_quota_bytes": # we store this metrics in a separate table to calculate disk usage later
 queue_quota.append({ "metric_name": sample.name, "md5_dims": hashlib.md5(str(dims).encode("utf-8")).hexdigest(), **dims, "METRICvalueMETRIC": sample.value})

 # send valid points (with dimensions strings as md5 if necessary)
 if sample.name not in censored_metrics_list:
 # Append valid points
 valid_points.append( { "metric_name": sample.name, **dims, "METRICvalueMETRIC": sample.value})
 else:
 # if the metric is aggregated we add a md5sum of "all the dimensions" as an index to find duplicates and ease "groupby" without pandas
 valid_points.append( { "metric_name": sample.name, "md5_dims": hashlib.md5(str(dims).encode("utf-8")).hexdigest(), **dims, "METRICvalueMETRIC": sample.value})

If this code is still correct in 0.22.1, I think there is an issue in newer versions 0.22.x.

Best regards,
Charles

[csmarchbanks]

Hello, thank you for the report, there were a couple of significant changes to parsing that were released in 0.22. Just to make sure, you are importing prometheus_client.parser not openmetrics correct? If so my guess is #1070 is having performance issues and we can look at creating some benchmarks to improve the performance.

[osd42]

Hello,
Here is my import

from prometheus_client.parser import text_string_to_metric_families

The example was found on this documentation.

Best regards,
Charles

[csmarchbanks]

Thanks! I'll take a look when I can.

[csmarchbanks]

I started looking into this by creating a benchmark (see #1116), however I am seeing basically identical mean performance when switching between 0.21.1 and 0.22.1. Is there something about the data that I could change to be more representative of your use case?

v0.21.1

------------------------------------------------------------------- benchmark: 1 tests ------------------------------------------------------------------
Name (time in ns) Min Max Mean StdDev Median IQR Outliers OPS (Mops/s) Rounds Iterations
---------------------------------------------------------------------------------------------------------------------------------------------------------
test_benchmark_text_string_to_metric_families 125.0000 2,132.6842 132.6872 11.6190 131.5789 1.0789 4043;20506 7.5365 198334 38
---------------------------------------------------------------------------------------------------------------------------------------------------------

v0.22.1

----------------------------------------------------------------- benchmark: 1 tests ----------------------------------------------------------------
Name (time in ns) Min Max Mean StdDev Median IQR Outliers OPS (Mops/s) Rounds Iterations
-----------------------------------------------------------------------------------------------------------------------------------------------------
test_benchmark_text_string_to_metric_families 127.0800 866.2500 133.1531 7.3024 132.0900 1.2400 1913;4980 7.5102 75234 100
-----------------------------------------------------------------------------------------------------------------------------------------------------

[osd42]

Hello @csmarchbanks,
I am working in a large company. The Prometheus exporters I am scrapping with the client_python lib are about a Solace Pubsub: the dataset is very very big. It is so big that we need to parallelize a lot of scrapping endpoints for the same Solace Broker Prometheus API.
Perhaps you can try to benchmark (1000 times, 10000 times) more prometheus lines to reproduce a significant downgraded performance.

I tried to calculate the number of prometheus line we do ingest on 1 broker endpoints between 2 garbage collectors for 1 solace broker: 37 004 / minute. As you see in my code, we sort out which line should be ingested or not. So I estimate we read 100000 lines / minute for the biggest broker. Then, on the same (dynatrace ActiveGate) machine, we configure multiple exporters which scrape multiple endpoints of multiple Solace Brokers.
On the production environment where CPU usage is 4 times higher, we are scrapping 9 brokers (between 18 and 27 prometheus endpoints), so to get the performance issue, perhaps 900000 lines per minute should be a representative benchmark.

I hope this helps.

Best regards,
Charles

[csmarchbanks]

Turns out I just needed to make sure to iterate across everything yielded by the generator and the regression shows up. My first attempt was only calculating the time to return the first metric family... The small benchmark I created now shows results taking 5-6x as long which is close enough to your report.

I'll look into optimizing the new codepath next!

[csmarchbanks]

I created a first batch of optimizations that according to the benchmark should help, but won't be back to original performance yet: #1117. If you have a chance I'd love to double check that those help your environment as well.