Execution time increasing with more connections

[gauravsingh-nagarro-scm-serv]

We are using Nebula v3.1 and Golang SDK v3
we are trying to check max connections supported by Nebula and tried to create multiple goroutines call which are concurrent calls to create session and execute query from Nebula.
Findings ->One goroutine which is trying to make 250 sessions to execute the query is taking 8s and if we add 4 goroutines where each goroutine trying to do same to loop over and make 250 sessions to execute query took 47s.
As we are running goroutines which are going concurrently, so wondering why total time taken to execute 250 queries got increased where it should be maximum of any of those 4 goroutine execution time as per my understanding.

Please find the code which reproduce the issue and let us know if there is any issue with our implementation->

package main


import (
    "fmt"
    "sync"
    "time"
    nebula "github.com/vesoft-inc/nebula-go/v3"
)


const (
    address  = "nebula host address"
    port     = 9669
    username = //username
    password = //password
)

var wg sync.WaitGroup
var Pool *nebula.ConnectionPool


func DbCall(i int) {
    defer wg.Done()
    session, err := Pool.GetSession(username, password)
    if err != nil {
        log.Fatal(fmt.Sprintf("Fail to create a new session from connection pool, username: %s, password: %s, %s",
            username, password, err.Error()))
    }
    defer session.Release()

    // Excute a query
    session.Execute("USE Space")

    resultSet, err := session.Execute("FETCH PROP ON Player \"Sam\" YIELD properties(vertex) AS Result")
    if err != nil {
        fmt.Print(err.Error())
        return
    }
    fmt.Println("Go Routine: ", i, " : ", resultSet.AsStringTable())
}


// Initialize logger
var log = nebula.DefaultLogger{}

func main() {
    hostAddress := nebula.HostAddress{Host: address, Port: port}
    hostList := []nebula.HostAddress{hostAddress}
    // Create configs for connection pool using default values
    testPoolConfig := nebula.GetDefaultConf()
    testPoolConfig.MaxConnPoolSize = 1000
    testPoolConfig.MinConnPoolSize = 500
    var err error

    // Initialize connection pool
    Pool, err = nebula.NewConnectionPool(hostList, testPoolConfig, log)
    if err != nil {
        log.Fatal(fmt.Sprintf("Fail to initialize the connection pool, host: %s, port: %d, %s", address, port, err.Error()))
    }
    // Close all connections in the pool
    defer Pool.Close()
    t := time.Now()
    wg.Add(4)
     go GoRoutine(0, 250)
     go GoRoutine(250, 500)
     go GoRoutine(500, 750)
     go GoRoutine(750, 1000)

    wg.Wait()
    fmt.Println(time.Since(t))
    // 11min for 10000 conn
    // 1m9.389(70 sec) sec for 1000 conn - 52 ms(500minConns),47sec(500,2 goroutines) - 47sec (500, 4 GR),38.9(800,2 goroutines), 32.4 sec(1000minCon, 2 goroutines), 1min7sec (100minConns, 2goroutines)
    // 35.41 sec for 500 conn
    // 7.11 sec for 100 conn - 5sec
    // 800 ms for 10 conn
}



func GoRoutine(start, end int) {
    defer wg.Done()
    for i := start; i < end; i++ {
        wg.Add(1)
        // Create session
        go DbCall(i)
    }

}```

[akhilravuri-tul-scm]

Hi @gauravsingh-nagarro-scm-serv

Thanks for raising this discussion. We are also facing the same issue.

@wey-gu sorry for tagging you.
Do you have any suggestions on this?

Thanks,
Akhil

[wey-gu]

@Aiee could you please help advice on this?

[Aiee]

Hello @gauravsingh-nagarro-scm-serv

One possible cause could be the cost of frequent construction/destruction of sessions in the meta service. In the sample code you post you are actually running 1000 goroutines to generate new sessions, execute queries, and release the sessions. Those session-related operations require some lock mechanism in the meta service because they are stored in a container.

BTW, the max connection number is unint64_max and can be configured by setting max_allowed_connections in the graph config.

[gauravsingh-nagarro-scm-serv]

hi @Aiee,thanks for the reply.
Is PoolConfig.MaxConnPoolSize and max_allowed_connections are same?
Also where we can configure this parameter max_allowed_connections in graphd config, not able to find this parameter in Nebula graphd configuration documentation.

We would be having 5000-10000 request/second coming so we need connection pool of almost 10000 session in pool to fulfill the request instead of creating new session every time. So if we keep min connection pool size as 10000 supposedly so when graphd service starts, it will create a connection pool of 10000 sessions in my understanding. Will it help to not have locks due to session creation/destruction as we already have 10000 session in pool to serve the request?

[gauravsingh-nagarro-scm-serv]

hi @Aiee , @wey-gu , We were checking the Nebula stats by running curl -G "http://ip:19669/stats" in graphd and found few attributes but not able to understand if these values are in milliseconds?

query_latency_us.avg.5=0 query_latency_us.avg.60=1131 query_latency_us.avg.600=1048 query_latency_us.avg.3600=1048 query_latency_us.p75.5=0 query_latency_us.p75.60=960 query_latency_us.p75.600=1204 query_latency_us.p75.3600=1204 query_latency_us.p95.5=0 query_latency_us.p95.60=4337 query_latency_us.p95.600=1923 query_latency_us.p95.3600=1923 query_latency_us.p99.5=0 query_latency_us.p99.60=5533 query_latency_us.p99.600=5063 query_latency_us.p99.3600=5063 query_latency_us.p999.5=0 query_latency_us.p999.60=5802 query_latency_us.p999.600=6388 query_latency_us.p999.3600=6388

If they are in milliseconds then looks like it took seconds latency for running 100 concurrent queries.
Can you give us some pointer how we can know what is causing this high latency and areas of reducing this latency.

As while running k6 , we saw with increased virtual users, execution time is also increasing. So it would be of great help what areas we should look for to reduce the query execution time(3 graphd node,1 metad node,3 storage node)