[BUG] 1.3.12 library release high CPU usage when communicating with redis cluster

[mike1821]

Hello @sewenew,

How are you?

Describe the bug I noticed a significant increment in CPU usage of library version 1.3.12 in comparison to 1.3.10. More specifically I noticed that when I am using a cluster the CPU usage to process HSET commands, using Generic Command Interface, is almost double in comparison to 1.3.10 release CPU usage. Please note that also the number of operation per second is lower.

Please note that I did not observe ant CPU usage increase between 1.3.10 and 1.3.12 when I did not use redis cluster mode.

I believe the problem, if any, introduced with the fix of issue 537. I noticed the CPU increment back then, but I did not have the time to investigate it further. Below are some metrics regarding the CPU usage.

CLUSTER

***** 1.3.10 (40% CPU usage) Total rate: 4850.75 ops/sec. Interval rate: 5000 ops/sec. Took: 200(msec)

**** 1.3.12 (75% CPU usage) Total rate: 4341.46 ops/sec. Interval rate: 4385.96 ops/sec. Took: 228(msec)

NO CLUSTER ***** 1.3.10 (35% CPU usage) Total rate: 4934.94 ops/sec. Interval rate: 4975.12 ops/sec. Took: 201(msec)

***** 1.3.12 (35% CPU usage) Total rate: 4911.57 ops/sec. Interval rate: 4878.05 ops/sec. Took: 205(msec)

To Reproduce

Below is a stripped down version of the client I used in order to simulate the issue. I have compiled it using: g++ -std=c++17 -o client client.cpp -lredis++ -lhiredis -pthread

#include <sw/redis++/async_redis_cluster.h>
#include <chrono>
#include <iostream>
#include <thread>
#include <mutex>
#include <condition_variable>
#include <vector>
#include <random>
#include <deque>
#include <unistd.h>

using namespace sw::redis;
using namespace std::chrono;

const int KEYS_PER_OPERATION = 1000;
const int DELETE_KEYS_COUNT = 300;
const int THROTTLE_THRESHOLD = 10000;

void timespec_diff(const timespec *start, const timespec *end, timespec *diff) 
{
    if ((end->tv_nsec - start->tv_nsec) < 0) {
        diff->tv_sec = end->tv_sec - start->tv_sec - 1;
        diff->tv_nsec = 1000000000 + end->tv_nsec - start->tv_nsec;
    } else {
        diff->tv_sec = end->tv_sec - start->tv_sec;
        diff->tv_nsec = end->tv_nsec - start->tv_nsec;
    }
}

unsigned long timespec_to_ms(const timespec *ts) 
{
    return ts->tv_sec * 1000 + ts->tv_nsec / 1000000;
}

void throttle_logic(unsigned long count, timespec &start, timespec &mid, timespec &now) 
{
    static unsigned long last_count = 0;  // Store the count from the last interval

    if (THROTTLE_THRESHOLD > 0 && count > 0 && (count % KEYS_PER_OPERATION == 0)) {
        timespec tsdiff;
        clock_gettime(CLOCK_MONOTONIC, &now);

        timespec_diff(&start, &now, &tsdiff);
        unsigned long ms_total = timespec_to_ms(&tsdiff);
        double produce_rate_total = 1000 * (double)count / (double)ms_total;

        timespec_diff(&mid, &now, &tsdiff);
        unsigned long ms_interval = timespec_to_ms(&tsdiff);

        unsigned long interval_ops = count - last_count;
        double produce_rate_interval = 1000 * (double)interval_ops / (double)ms_interval;

        static int iteration = 1;
        std::cout << "Total rate: " << produce_rate_total << " ops/sec. " 
                  << "Interval rate: " << produce_rate_interval << " ops/sec. Took: " << ms_interval << std::endl;

        last_count = count;

    }
}

void create_keys(AsyncRedisCluster &redis, unsigned long &count, std::mutex &count_mutex, std::condition_variable &cv, bool &ready);

int main()
{
    sw::redis::ConnectionOptions opts;
    opts.host = "127.0.0.1";
    opts.port = 6379;

    sw::redis::AsyncRedisCluster redis(opts);

    unsigned long count = 0;
    std::mutex count_mutex;
    std::condition_variable cv;
    bool ready = false;

    std::thread create_thread(create_keys, std::ref(redis), std::ref(count), std::ref(count_mutex), std::ref(cv), std::ref(ready));

    create_thread.join();

    return 0;
}

void create_keys(AsyncRedisCluster &redis, unsigned long &count, std::mutex &count_mutex, std::condition_variable &cv, bool &ready) 
{
    timespec start, mid , now;
    clock_gettime(CLOCK_MONOTONIC, &start);

    while (true) 
    {
        {
            std::lock_guard<std::mutex> lock(count_mutex);

            for (int i = 0; i < KEYS_PER_OPERATION; ++i) {
                std::string key = "{key-" + std::to_string(count + i) + "}";

                std::vector<std::string> raw_cmd = {
                    "HSET", // HSET command
                    key    // Redis key
                };

                // Adding field-value pairs
                for (int j = 0; j < 10; j++) {
                    raw_cmd.push_back("field" + std::to_string(j));
                    raw_cmd.push_back("value" + std::to_string(j));
                }

                // Send HSET command to Redis
                auto db_client = redis.redis(key, false); 
                db_client.command<long long>(raw_cmd.begin(), raw_cmd.end(),
                    [key](Future<long long> &&fut) {
                        try {
                            long long result = fut.get();
                        } catch (const Error &e) {
                            std::cerr << "HSET Error: " << key << " - " << e.what() << std::endl;
                        }
                    }
                );
                usleep(100);
            }
            count += KEYS_PER_OPERATION;
            throttle_logic(count, start, mid, now);
            clock_gettime(CLOCK_MONOTONIC, &mid);
        }

        {
            std::lock_guard<std::mutex> lock(count_mutex);
            ready = true;
        }
        cv.notify_all();
    }
}

I would much appreciate it, if you could spend some time to check this issue. Please let me know if any further information are required.

Environment: OS: Rocky Linux Compiler: g++ 8.5.0 hiredis version: v1.1.0, master] redis-plus-plus version: 1.3.10/1.3.12

BR, Michalis

[sewenew]

I think the problem is that redis-plus-plus updates the underlying slot-node mapping every time you call AsyncRedisCluster::redis.

I've modified this behavior, and update the slot-node mapping every ClusterOptions::slot_map_refresh_interval (by default, it updates every 10 seconds). The code is ready on the dev branch. You can test with it. If there's no problem, I'll merge the code into master branch.

Thanks for pointing out the problem!

Regards

[mike1821]

Hello,

Thank you for your quick response. I did test the new library and indeed the CPU usage decreased to a level similar to 1.3.10 release.

Please note that, I tested using different slot_map_refresh_interval(s) as well without noticing any significant differences.

Best regards

[sewenew]

Code has been merged into master branch. I did some tests before the merge, sorry for the delay.

Regards