Abstract

This document describes analyzing performance of CPS/NCMP using Prometheus metrics and analyzing performance of SQL queries.

This guide will use case studies of analyzing performance of some NCMP operations, and be able to answer the following questions:

• What methods take the most time?

• What percentage of time is spent in the Database, Hazelcast, Java, and DMI?

Additionally, there are some instructions on doing deeper performance analysis of SQL queries.

Gathering metrics on a laptop

Disabling Turbo Boost on CPU

Some CPUs have a feature called dynamic frequency scaling which allows the CPU to run at a higher clock speed when running demanding tasks. Intel processors call this Turbo Boost. While the feature can improve performance, it can make testing very unstable, as the system may overheat and throttle when running sustained loads. This is because Turbo Boost allows the system to exceed Thermal Design Power (TDP).

Additionally, the server running NCMP KPI Jenkins pipeline job has clock speed of around 2.5 GHz. On a laptop with i9, the max clock speed is 2.6 GHz with turbo off, 5.0 GHz with turbo on. Disabling it will give a better approximation of server performance.

It is needed to disable Turbo Boost if running performance tests on a laptop, otherwise test results will fluctuate wildly between runs. Here are instructions to disable it on Dell XPS laptops: Tutorial on disable Turbo boost within BIOS | Dell Ireland

Running k6 tests on a laptop

Running the k6 tests is straightforward. From the command line, go to the cps repo and execute:

As can be seen below, the script will install needed dependencies, and kick of the KPI test suite:

After around 30 minutes, you will see a test report - note the CSV report can be copy-pasted into a spreadsheet for further analysis if needed.:

Finally, the docker environment will be shut down:

Tips & Tricks for running quick tests

To Do: Document which variables to change for quicker test runs: 20k, removing shutdown delay, lowering initial module delay, lowering test durations, etc.

Analyzing SQL queries in Postgresql

During performance analysis of operations in CPS/NCMP, it will often be the case that much time is spent in database queries. Postgres can be used to analyze performance using the EXPLAIN ANALYZE command. But in order to run those queries used in NCMP, it’s necessary to populate the database with realistic data. We will do this by running the k6 tests to do CM-handle registration.

Populating the database with CM-handles

A k6 script will be used to populate the database with CM-handles. Start docker-compose using kpi profile, and run the k6 script to register CM-handles:

The system will now be running and populated with CM-handles.

Connecting to the database

You will need a Postgresql client for this. On Ubuntu Linux, you can install the postgresql client:

On command line, connect to the database using psql to localhost port 5432:

The default password is ‘cps’.

You can verify that the database is populated by examining the dataspace/anchor/fragment tables. For example:

Analyzing SQL queries

Let’s say you wish to analyze the performance of the query to get a dataspace by name. First run the query to make sure it returns the expected result:

Now you may analyze performance with EXPLAIN ANALYZE:

In the above case, it can be seen that database is using and Index Scan to find the row, which is very efficient. You can also see the time taken to plan and execute the query.

Shutting down test deployment

When you are finished analysis, you can shut down the system using docker-compose down:

Profiling code with reports of @Timed annotations

Within the cps repo, there is a folder called ‘test-tools’ which contains some scripts useful for generating reports.

Generating reports

Running the generate-metrics-report.sh script will generate a report and output the filename of it:

Opening the generated file in a spreadsheet will show a report of exposed Prometheus metrics from CPS/NCMP. It shows the count (how many times the method was called) and the sum (total amount of time spent in that method):

Open

Subtracting reports

It is useful to be able to subtract two reports to generate a delta report. Exposed metrics are cumulative from the application startup, but many times you will only want metrics during a given time. For example, when testing NCMP operations, you may want to exclude set up time like CM-handle registration, and only include metrics while running a test case.

Given you have two reports, you can use the script ‘subtract-metrics-reports.py’ to generate a delta report:

-a specifies the later report (after)
-b specifies the earlier report (before)
-o specifies the name of the output file

Note you are likely to encounter an error if you are running two instances of NCMP, as each instance have their own metrics. It is recommended to change the docker-compose.yml to have 1 replica of cps-and-ncmp container to prevent this.

Generating report for a single test case

The basic flow is this:

1. Modify docker-compose.yml to set 1 replica for cps-and-ncmp container.

2. Modify the k6 config (k6-tests/ncmp/config/kpi.json) to remove scenarios you are not interested in.

3. Run the k6 tests using k6-tests/run-k6-tests.sh

4. Wait until registration is finished (e.g. monitoring docker logs: docker logs -f kpi-nginx-loadbalancer)

5. Take a metrics report using generate-metrics-report.sh

6. Wait a few minutes

7. Take another metrics report using generate-metrics-report.sh

8. Subtract the two reports using subtract-metrics-reports.py

9. Review the results.

Adding new metrics

The metric reports will only show metrics that are exposed in the application. If you want to add new metrics, you may add @Timed annotations to methods in the Java code and recompile. For example:

Case Studies

Note: many code changes were made since these two analyses were made. As such, they are just examples and do not reflect current performance.

Example Analysis: NCMP overhead for Synchronous single CM-handle pass-through read with alternate id

Modify the k6 test config so it only includes the scenario of passthrough read with alternate ID - just delete all the others from k6-tests/ncmp/config/kpi.son:

Then follow the outlined steps in Performance testing CPS/NCMP using metrics | Generating report for a single test case

The output file will look something like this:

From the above, nearly all time is spent in the http server call to /ncmp/v1/ch/{cm-handle}/data/ds/{datastore-name} - which is the Rest endpoint for the passthrough data request. Following this, most of the time is in NetworkCmProxyController. The third most frequent

Example Analysis: CM-handle search with Property filter

Rerunning above with only the k6 scenario cm_handle_search_property_scenario will give output like this:

As can be seen:

• 33.77 seconds were spent executing /ncmp/v1/ch/searches

• 29.69 seconds were spent in CpsDataService getDataNodesForMultipleXpaths.

• Thus 88% of the total request time was in the getDataNodesForMultipleXpaths method.