sonic-db-cli high CPU usage on SONiC startup

[stepanblyschak]

Description

sonic-db-cli high CPU usage on SONiC startup

Steps to reproduce the issue:

1. Install and start bootchart2
2. Regular boot
3. Generate bootchart2 plot

Describe the results you received:

Looking at the bootchart plots we see an enormous amount of CPU time taken by sonic-db-cli.

It’s in python and most time spent in python libraries on import time. I have done some small experiment rewriting this utility in C++ (the PoC code attached) since this utility is quite simple.
It gave another 5 sec improvement and the sonic-db-cli disappeared from the plot:

Describe the results you expected:

Low CPU usage of sonic-db-cli.

Output of show version:

SONiC Software Version: SONiC.202111.28-714797af3_Internal
Distribution: Debian 11.2
Kernel: 5.10.0-8-2-amd64
Build commit: 714797af3
Build date: Wed Mar  9 08:17:21 UTC 2022
Built by: sw-r2d2-bot@r-build-sonic-ci02-241

Platform: x86_64-mlnx_msn2700-r0
HwSKU: Mellanox-SN2700
ASIC: mellanox
ASIC Count: 1
Serial Number: MT1805K20439
Model Number: MSN2700-CS2F
Hardware Revision: A2
Uptime: 11:57:10 up 21:10,  2 users,  load average: 0.78, 0.64, 0.65

Docker images:
REPOSITORY                    TAG                            IMAGE ID       SIZE
docker-syncd-mlnx             202111.28-714797af3_Internal   c393eaafb38e   923MB
docker-syncd-mlnx             latest                         c393eaafb38e   923MB
docker-teamd                  202111.28-714797af3_Internal   121a4e41a663   440MB
docker-teamd                  latest                         121a4e41a663   440MB
docker-sflow                  202111.28-714797af3_Internal   21f51e9a19e5   441MB
docker-sflow                  latest                         21f51e9a19e5   441MB
docker-platform-monitor       202111.28-714797af3_Internal   731ff4d0033e   811MB
docker-platform-monitor       latest                         731ff4d0033e   811MB
docker-orchagent              202111.28-714797af3_Internal   c480cae89a7c   459MB
docker-orchagent              latest                         c480cae89a7c   459MB
docker-nat                    202111.28-714797af3_Internal   4a83166bab19   443MB
docker-nat                    latest                         4a83166bab19   443MB
docker-macsec                 202111.28-714797af3_Internal   8a2bd19a2842   444MB
docker-macsec                 latest                         8a2bd19a2842   444MB
docker-fpm-frr                202111.28-714797af3_Internal   1b55bf0998eb   459MB
docker-fpm-frr                latest                         1b55bf0998eb   459MB
docker-dhcp-relay             latest                         9df7bee25ad4   444MB
docker-sonic-mgmt-framework   202111.28-714797af3_Internal   339160ca5c13   587MB
docker-sonic-mgmt-framework   latest                         339160ca5c13   587MB
docker-router-advertiser      202111.28-714797af3_Internal   86c636856cca   426MB
docker-router-advertiser      latest                         86c636856cca   426MB
docker-sonic-telemetry        202111.28-714797af3_Internal   e2e535560cb9   514MB
docker-sonic-telemetry        latest                         e2e535560cb9   514MB
docker-snmp                   202111.28-714797af3_Internal   9f2b5141f104   469MB
docker-snmp                   latest                         9f2b5141f104   469MB
docker-mux                    202111.28-714797af3_Internal   dd18beabfa25   478MB
docker-mux                    latest                         dd18beabfa25   478MB
docker-lldp                   202111.28-714797af3_Internal   909828c23746   466MB
docker-lldp                   latest                         909828c23746   466MB
docker-database               202111.28-714797af3_Internal   60c49237e5a6   426MB
docker-database               latest                         60c49237e5a6   426MB

Output of show techsupport:

(paste your output here or download and attach the file here )

Additional information you deem important (e.g. issue happens only occasionally):

[qiluo-msft]

Thanks for raising the issue and detailed analysis! Could you attach "the PoC code"? Are you able to submit a PR (may in draft) and we can keep discussing on PR.

[stepanblyschak]

@qiluo-msft

The code that I used for test:

#include <swss/sonicv2connector.h>

#include <getopt.h>
#include <unistd.h>

#include <iostream>
#include <string>
#include <vector>

static std::string nameSpace;
static std::string dbOrOperation;
static std::vector<std::string> commands;

static int useUnixSocket;
static int helpRequested;

void printUsage()
{
    std::cerr << "usage: sonic-db-cli [-h] [-s] [-n NAMESPACE] db_or_op [cmd ...]" << std::endl;
}

void parseCliArguments(int argc, char** argv)
{
    for (int index = 1; index < argc; index++)
    {
        std::string opt{argv[index]};
        if (opt == "-h" || opt == "--help")
        {
            helpRequested = true;
        }
        else if (opt == "-n" || opt == "--namespace")
        {
            index++;
            if (index == argc)
            {
                throw std::invalid_argument("namespace option requires argument");
            }
            nameSpace = argv[index];
        }
        else if (opt == "-s" || opt == "--unixsocket")
        {
            useUnixSocket = true;
        }
        else
        {
            if (dbOrOperation.empty())
            {
                dbOrOperation = argv[index];
            }
            else
            {
                commands.emplace_back(argv[index]);
            }
        }
    }
}

void printRedisReply(redisReply* reply)
{
    switch(reply->type)
    {
    case REDIS_REPLY_INTEGER:
        std::cout << reply->integer;
        break;
    case REDIS_REPLY_STRING:
    case REDIS_REPLY_ERROR:
    case REDIS_REPLY_STATUS:
    case REDIS_REPLY_NIL:
        std::cout << std::string(reply->str, reply->len);
        break;
    case REDIS_REPLY_ARRAY: 
        for (size_t i = 0; i < reply->elements; i++)
        {
            printRedisReply(reply->element[i]);
        }
        break;
    default:
        std::cerr << reply->type << std::endl;
        throw std::runtime_error("Unexpected reply type");
    }

    std::cout << std::endl;
}

void executeCommands(const std::string& dbname, std::vector<std::string>& commands)
{
    swss::SonicV2Connector_Native conn(useUnixSocket, nameSpace.c_str());
    conn.connect(dbname);
    auto& client = conn.get_redis_client(dbname);
    
    swss::RedisCommand r;

    size_t argc = commands.size();
    const char** argv = new const char*[argc];
    size_t* argvc = new size_t[argc];

    for (size_t i = 0; i < argc; i++)
    {
        argv[i] = strdup(commands[i].c_str());
        argvc[i] = commands[i].size();
    }

    swss::RedisCommand c;
    c.formatArgv(argc, argv, argvc);
    swss::RedisReply reply(&client, c);

    auto redisReply = reply.getContext();
    printRedisReply(redisReply);
}

void handleSingleOperation(const std::string& ns, const std::string& operation)
{
    swss::SonicV2Connector_Native conn(useUnixSocket, ns.c_str());
    conn.connect("APPL_DB");
    auto& client = conn.get_redis_client("APPL_DB");
    
    swss::RedisReply reply(&client, operation);
    auto redisReply = reply.getContext();
    printRedisReply(redisReply);
}

void handleOperation()
{
    if (dbOrOperation == "PING" || dbOrOperation == "SAVE" || dbOrOperation == "FLUSHALL")
    {
        handleSingleOperation(nameSpace, dbOrOperation);
    }
    else if (!commands.empty())
    {
        executeCommands(dbOrOperation, commands);
    }
    else
    {
        throw std::runtime_error("Invalid operation");
    }
}

int main(int argc, char** argv)
{
    try
    {
        parseCliArguments(argc, argv);
        handleOperation();
    }
    catch (const std::exception& e)
    {
        std::cerr << e.what() << std::endl;
        return -1;
    }

    return 0;
}

[liuh-80]

ETA of this issue will be 2022/05/31

[stepanblyschak]

In 202111 an image built from commit 9b4387a does not execute sonic-db-cli C++ version:

admin@arc-switch1004:~$ show version

SONiC Software Version: SONiC.202111.0-9b4387ace
Distribution: Debian 11.3
Kernel: 5.10.0-8-2-amd64
Build commit: 9b4387ace
Build date: Thu Jun 30 19:16:09 UTC 2022
Built by: stepanb@r-build-sonic03

Platform: x86_64-mlnx_msn2700-r0
HwSKU: Mellanox-SN2700-D48C8
ASIC: mellanox
ASIC Count: 1
Serial Number: MT1805K20439
Model Number: MSN2700-CS2F
Hardware Revision: A2
Uptime: 09:46:14 up 5 min,  1 user,  load average: 1.84, 1.95, 1.03

Docker images:
REPOSITORY                    TAG                  IMAGE ID       SIZE
docker-fpm-frr                202111.0-9b4387ace   af2b876f0366   461MB
docker-fpm-frr                latest               af2b876f0366   461MB
docker-orchagent              202111.0-9b4387ace   53cb13d3917e   460MB
docker-orchagent              latest               53cb13d3917e   460MB
docker-teamd                  202111.0-9b4387ace   0922618fee97   443MB
docker-teamd                  latest               0922618fee97   443MB
docker-sflow                  202111.0-9b4387ace   ebebaa63365b   443MB
docker-sflow                  latest               ebebaa63365b   443MB
docker-nat                    202111.0-9b4387ace   062829074cdb   445MB
docker-nat                    latest               062829074cdb   445MB
docker-platform-monitor       202111.0-9b4387ace   44976ab250ab   820MB
docker-platform-monitor       latest               44976ab250ab   820MB
docker-macsec                 202111.0-9b4387ace   6d4ee660f123   446MB
docker-macsec                 latest               6d4ee660f123   446MB
docker-snmp                   202111.0-9b4387ace   bf4760f6990d   472MB
docker-snmp                   latest               bf4760f6990d   472MB
docker-dhcp-relay             latest               69ef78e1cc5d   442MB
docker-syncd-mlnx             202111.0-9b4387ace   10fc9ef8da3c   928MB
docker-syncd-mlnx             latest               10fc9ef8da3c   928MB
docker-lldp                   202111.0-9b4387ace   9e32109cee23   469MB
docker-lldp                   latest               9e32109cee23   469MB
docker-database               202111.0-9b4387ace   736867bbb30f   428MB
docker-database               latest               736867bbb30f   428MB
docker-sonic-mgmt-framework   202111.0-9b4387ace   c7d7e5445fe3   583MB
docker-sonic-mgmt-framework   latest               c7d7e5445fe3   583MB
docker-sonic-telemetry        202111.0-9b4387ace   22d3852d8dc5   517MB
docker-sonic-telemetry        latest               22d3852d8dc5   517MB
docker-router-advertiser      202111.0-9b4387ace   74336f627269   429MB
docker-router-advertiser      latest               74336f627269   429MB
docker-mux                    202111.0-9b4387ace   219a05f2d31d   481MB
docker-mux                    latest               219a05f2d31d   481MB

admin@arc-switch1004:~$ which sonic-db-cli
/usr/local/bin/sonic-db-cli
admin@arc-switch1004:~$ head /usr/local/bin/sonic-db-cli
#!/usr/bin/python3
from __future__ import print_function
import sys
import swsssdk
import redis
import argparse
from multiprocessing import Pool
from functools import partial

def handle_single_instance(op, use_unix_socket, inst_info):

[qiluo-msft]

@liuh-80 Could you summarize all the PR related to this fix into a markdown table? Check the Sample.

Then we need to mark each PR with cherry-pick labels for 202111 and 202205.

[liuh-80]

Here are summary of all PRs related to this fix, all PRs are tagged with 202111 and 202205:

PR title	state	context
[sonic-swss-common] Re-write sonic-db-cli with c++ for sonic startup performance issue
[sonic-swss-common] Fix sonic-db-cli output format not backward compatible with python version issue.
[sonic-swss-common] Fix PING database command not return bool string issue.
[sonic-py-swsssdk] Remove sonic-db-cli from swsssdk
[sonic-buildimage] Add c++ version sonic-db-cli from sonic-swss-common
[sonic-buildimage] Update src/sonic-py-swsssdk
[sonic-swss] Purge package sonic-db-cli which depends on libswsscommon
[sonic-swss] Fix: missing sonic-db-cli in docker-sonic-vs image
[sonic-swss-common] Purge package sonic-db-cli which depends on libswsscommon
[sonic-swss-common] Fix: missing sonic-db-cli in docker-sonic-vs image
[sonic-sairedis] Purge package sonic-db-cli which depends on libswsscommon
[sonic-sairedis] Fix: missing sonic-db-cli in docker-sonic-vs image