Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Godror failing to handle enough concurrent connections. #192

Closed
monirz opened this issue Oct 19, 2021 · 34 comments
Closed

Godror failing to handle enough concurrent connections. #192

monirz opened this issue Oct 19, 2021 · 34 comments

Comments

@monirz
Copy link

monirz commented Oct 19, 2021

Hi,

We have a server that can handle 60,000+ concurrent request but that doesn't hit the database. But with an API that excepts JSON data and insert into database, that fails with 20,000 concurrent request. Although it works fine with 10k requests. I have also tried stop calling the db insert function with that API and it works fine.

Now with around 20k request it throws an error like this, here is the stacktrace:

goroutine 22214 [syscall, locked to thread]:
github.com/godror/godror._Cfunc_dpiConn_create(0x28e55a0, 0x0, 0x0, 0x0, 0xc000000000, 0x7fe1e9571430, 0x3f, 0x0, 0xc02d86b830, 0xc02dbaa068, ...)
	_cgo_gotypes.go:2273 +0x4b
github.com/godror/godror.(*drv).acquireConn.func8.1(0xb31aa0, 0xc02dbed6d0, 0x0, 0x0, 0xc02dbed6d8, 0x0, 0x0, 0xc02dbed6e8, 0xc02dbeda50, 0x0, ...)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/godror/godror/drv.go:559 +0x1a5
github.com/godror/godror.(*drv).acquireConn.func8(0x41b818)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/godror/godror/drv.go:559 +0x91
github.com/godror/godror.(*drv).checkExec(0xb31aa0, 0xc02dbed810, 0x0, 0x0)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/godror/godror/drv.go:258 +0x5a
github.com/godror/godror.(*drv).acquireConn(0xb31aa0, 0xc0001bee00, 0xc00030093c, 0x5, 0xc000398640, 0x3f, 0xc0003007c0, 0x8, 0x0, 0x0, ...)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/godror/godror/drv.go:552 +0x731
github.com/godror/godror.(*drv).createConn(0xb31aa0, 0xc0001bee00, 0xc00030093c, 0x5, 0xc000398640, 0x3f, 0xc0003007c0, 0x8, 0x0, 0x0, ...)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/godror/godror/drv.go:372 +0xd8
github.com/godror/godror.(*drv).createConnFromParams(0xb31aa0, 0xc00030093c, 0x5, 0xc000398640, 0x3f, 0xc0003007c0, 0x8, 0x0, 0x0, 0x0, ...)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/godror/godror/drv.go:589 +0x158
github.com/godror/godror.connector.Connect(0xb31aa0, 0xc00030093c, 0x5, 0xc000398640, 0x3f, 0xc0003007c0, 0x8, 0x0, 0x0, 0x0, ...)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/godror/godror/drv.go:1089 +0x6f8
database/sql.(*DB).conn(0xc000079e10, 0x8ff028, 0xc02dba2960, 0x7fe4080c1d01, 0x0, 0x1c0, 0x7ff2f74fb5b8)
	/usr/local/go/src/database/sql/sql.go:1301 +0x184
database/sql.(*DB).exec(0xc000079e10, 0x8ff028, 0xc02dba2960, 0x891998, 0x6f, 0xc02dbef0a8, 0x5, 0x5, 0x1, 0x10, ...)
	/usr/local/go/src/database/sql/sql.go:1553 +0x66
database/sql.(*DB).ExecContext(0xc000079e10, 0x8ff028, 0xc02dba2960, 0x891998, 0x6f, 0xc02dbef0a8, 0x5, 0x5, 0xc02dba8580, 0x0, ...)
	/usr/local/go/src/database/sql/sql.go:1535 +0xe5
phcgolang/orcl.(*HouseService).CreateHouse(0xc00000ec48, 0x8ff060, 0xc02dba2960, 0xc02dbb3500, 0x1, 0x4, 0xc02d9182a0, 0x0, 0x0)
	/home/monir/gocode/src/github.com/username/project/orcl/house.go:62 +0x3a5
phcgolang/handler.(*Server).CreateHouseholdsHandler(0xc00043d680, 0x8fe460, 0xc02d8567e0, 0xc02d779c00)
	/home/monir/gocode/src/github.com/username/project/handler/house_handler.go:47 +0x422
net/http.HandlerFunc.ServeHTTP(0xc0003ded60, 0x8fe460, 0xc02d8567e0, 0xc02d779c00)
	/usr/local/go/src/net/http/server.go:2069 +0x44
phcgolang/handler.(*Server).JWT.func1(0x8fe460, 0xc02d8567e0, 0xc02d779c00)
	/home/monir/gocode/src/github.com/username/project/handler/middleware.go:43 +0x24c
net/http.HandlerFunc.ServeHTTP(0xc0003f3e60, 0x8fe460, 0xc02d8567e0, 0xc02d779c00)
	/usr/local/go/src/net/http/server.go:2069 +0x44
github.com/go-chi/chi.(*ChainHandler).ServeHTTP(0xc000409bc0, 0x8fe460, 0xc02d8567e0, 0xc02d779c00)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/go-chi/chi/chain.go:31 +0x52
github.com/go-chi/chi.(*Mux).routeHTTP(0xc0003f1920, 0x8fe460, 0xc02d8567e0, 0xc02d779c00)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/go-chi/chi/mux.go:436 +0x28b
net/http.HandlerFunc.ServeHTTP(0xc0003decd0, 0x8fe460, 0xc02d8567e0, 0xc02d779c00)
	/usr/local/go/src/net/http/server.go:2069 +0x44
github.com/go-chi/chi.(*Mux).ServeHTTP(0xc0003f1920, 0x8fe460, 0xc02d8567e0, 0xc02d779b00)
	/home/monir/gocode/src/github.com/username/project/vendor/github.com/go-chi/chi/mux.go:87 +0x331
net/http.serverHandler.ServeHTTP(0xc0000a8000, 0x8fe460, 0xc02d8567e0, 0xc02d779b00)
	/usr/local/go/src/net/http/server.go:2887 +0xa3
net/http.(*conn).serve(0xc02da49540, 0x8ff060, 0xc02d77f580)
	/usr/local/go/src/net/http/server.go:1952 +0x8cd
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:3013 +0x39b

From one of your suggestion I found I tried with context.WithTimeout(ctx, 1*time.Minute) and db.ExecContext() for executing the insert query. The result is same.

Here is my config for the Godror I'm using:

configDir= connectionClass= enableEvents=0 externalAuth=0 heterogeneousPool=0
libDir= noTimezoneCheck=0 poolIncrement=30 poolMaxSessions=20000 poolMinSessions=0
poolSessionMaxLifetime=0s poolSessionTimeout=15s poolWaitTimeout=0s prelim=0
standaloneConnection=0 sysasm=0 sysdba=0 sysoper=0 timezone=

If you want to know a little bit of server config:

	srv := &http.Server{
		Addr:         addr,
		ReadTimeout:  60 * time.Second,
		WriteTimeout: 60 * time.Second,
		Handler:      s.router,
	}

I'm currently trying with the client I have written in Golang, which has the http.Transport configuration like this:

tr = &http.Transport{
		Proxy: http.ProxyFromEnvironment,
		DialContext: (&net.Dialer{
			Timeout:   30 * time.Second,
			KeepAlive: 30 * time.Second,
		}).DialContext,
		MaxIdleConnsPerHost:   20000,
		MaxIdleConns:          100,
		IdleConnTimeout:       90 * time.Second,
		TLSHandshakeTimeout:   10 * time.Second,
		ExpectContinueTimeout: 1 * time.Second,
	}

I can show you the full client code if you want, but the thing is it successfully handles 10k+ requests, or I also tried tsung to generate the load, result is pretty much same. Our database is configured for 400k connections but the session is about 6k (Do we need to increase it?). Although no error from the database side.

And about the house data I'm sending it could be an array of house but right now I'm just only sending one house that has around 34 fields, mostly 1/2 digit integer value except for the uid field. But the insert query inserts into two tables one with a very few fields.

I have tried several ways to tweak the configuration and stuff and couldn't get it working. Our target is to reaching at least 60k concurrent requests. Is that a bug? Or What I might be doing wrong here? Can you give me any direction? Any help is appreciated!

Thank you!

@tgulacsi
Copy link
Contributor

What is the error (that's been omitted) ?

What if poolMinSessions=20000 (or something high enough to remove the churn)?
To have another limiter, use db.SetMaxConns(20000) (or less).

I don't know whether it's the pool session acquiring/releasing or something else causes the error.
but you can easily limit the concurrent database connection by spawning some goroutines that does the INSERTs. Or even batch them (see https://pkg.go.dev/github.com/godror/godror#Batch) and flush peridocally.

Is that 20k concurrent connections really needed?
Do they do really different things in really different transactions that must separately commit/rollback?
If you sacrifice latency or transactions, batching those inserts multiplies throughput.

@tgulacsi
Copy link
Contributor

A little background:
db.ExecContext will acquire a Go connection object. If none exist, will acquire an Oracle session and create the Go object.
The caching/limiting is db.SetMaxConns (upper limit), and db.SetMaxIdleConns.
The next level is Oracle session pooling.

So best is to have db.SetMaxConns < poolMaxSessions and db.SetMaxIdleConns >= (number of average concurrent requests).

@monirz
Copy link
Author

monirz commented Oct 20, 2021

Hi,

I didn't omit the error message, it just shows that with each failed request repeatedly when concurrency limit to set to 20k and the server crashes eventually.

So for the scenario we will have around 400k users which may hit the same time in worst case scenario. So we need to be prepared for that. Also 20k concurrent doesn't sound much, we need to reach at least 50k concurrent for each node for Golang API server. So it'll open 50k connections in the DB. It's a purchased ORACLE database and it is suppose to handle 400k connections.

So I have tried all the configuration you have mentioned, like set the poolMinSessions to 20000k: poolMinSessions=20000, also set the db.SetMaxConns and db.SetMaxIdleConns as you have mentioned but it didn't work out. Although I haven't tried the spawning a goroutine for the DB call yet.

I really appreciate your feedback, and giving me some direction. But at this point I'm a bit clueless. Is that something do with CGO or something? Also can you try reproducing the scenario? I can give you the needed code for the server and client.

Thank you!
Monir.

@tgulacsi
Copy link
Contributor

Sorry, but that's not an error message, just a stack trace.
Can you put a full log (which DPI_DEBUG_LEVEL=92) somewhere?

@monirz
Copy link
Author

monirz commented Oct 20, 2021

So, I have set the DPI_DEBUG_LEVEL=92 also now I'm trying in a total isolated environment where it's only trying to insert into one table with only few columns (although the result is same) on my local machine. And when I'm starting the server with DPI_DEBUG_LEVEL at first it shows something like this:

ODPI [484590] 2021-10-20 14:12:11.496: ODPI-C 4.3.0-dev
ODPI [484590] 2021-10-20 14:12:11.496: debugging messages initialized at level 92
2021/10/20 14:12:11 user=oradb password="SECRET-2lvNBrU8CpI=" connectString="localhost:49161/ORCLCDB.localdomain:dedicated?connect_timeout=5"
configDir= connectionClass= enableEvents=0 externalAuth=0 heterogeneousPool=0
libDir= noTimezoneCheck=0 poolIncrement=1 poolMaxSessions=20000 poolMinSessions=1
poolSessionMaxLifetime=0s poolSessionTimeout=15s poolWaitTimeout=0s prelim=0
standaloneConnection=0 sysasm=0 sysdba=0 sysoper=0 timezone=
ODPI [484590] 2021-10-20 14:12:11.497: fn start dpiContext_createWithParams
ODPI [484590] 2021-10-20 14:12:11.497: Context Parameters:
ODPI [484590] 2021-10-20 14:12:11.497: Environment Variables:
ODPI [484590] 2021-10-20 14:12:11.497:     LD_LIBRARY_PATH => ":/opt/oracle/instantclient_19_8"
ODPI [484590] 2021-10-20 14:12:11.497: check module directory
ODPI [484590] 2021-10-20 14:12:11.497: module name is /tmp/go-build3585627884/b001/exe/main
ODPI [484590] 2021-10-20 14:12:11.497: load in dir /tmp/go-build3585627884/b001/exe
ODPI [484590] 2021-10-20 14:12:11.497: load with name /tmp/go-build3585627884/b001/exe/libclntsh.so
ODPI [484590] 2021-10-20 14:12:11.497: load by OS failure: /tmp/go-build3585627884/b001/exe/libclntsh.so: cannot open shared object file: No such file or directory
ODPI [484590] 2021-10-20 14:12:11.497: load with OS search heuristics
ODPI [484590] 2021-10-20 14:12:11.497: load with name libclntsh.so
ODPI [484590] 2021-10-20 14:12:11.501: load by OS successful
ODPI [484590] 2021-10-20 14:12:11.501: validating loaded library
ODPI [484590] 2021-10-20 14:12:11.503: fn end dpiContext_createWithParams -> 0
ODPI [484590] 2021-10-20 14:12:11.503: fn start dpiContext_getClientVersion(0x19d4e70)
ODPI [484590] 2021-10-20 14:12:11.503: fn end dpiContext_getClientVersion(0x19d4e70) -> 0
ODPI [484590] 2021-10-20 14:12:11.503: fn start dpiContext_initCommonCreateParams(0x19d4e70)
ODPI [484590] 2021-10-20 14:12:11.503: fn end dpiContext_initCommonCreateParams(0x19d4e70) -> 0
ODPI [484590] 2021-10-20 14:12:11.503: fn start dpiContext_initPoolCreateParams(0x19d4e70)
ODPI [484590] 2021-10-20 14:12:11.503: fn end dpiContext_initPoolCreateParams(0x19d4e70) -> 0
ODPI [484590] 2021-10-20 14:12:11.503: fn start dpiPool_create(0x19d4e70)
ODPI [484590] 2021-10-20 14:12:11.534: fn end dpiPool_create(0x19d4e70) -> 0
ODPI [484590] 2021-10-20 14:12:11.534: fn start dpiPool_setStmtCacheSize(0x1a07c00)
ODPI [484590] 2021-10-20 14:12:11.534: fn end dpiPool_setStmtCacheSize(0x1a07c00) -> 0
ODPI [484590] 2021-10-20 14:12:11.534: fn start dpiContext_initConnCreateParams(0x19d4e70)
ODPI [484590] 2021-10-20 14:12:11.534: fn end dpiContext_initConnCreateParams(0x19d4e70) -> 0
ODPI [484590] 2021-10-20 14:12:11.534: fn start dpiConn_create(0x19d4e70)
ODPI [484590] 2021-10-20 14:12:11.534: fn end dpiConn_create(0x19d4e70) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiConn_prepareStmt(0x1a76160)
ODPI [484590] 2021-10-20 14:12:11.535: SQL SELECT DBTIMEZONE as dbTZ, NVL(TO_CHAR(SYSTIMESTAMP, 'tzr'), TO_CHAR(SYSTIMESTAMP, 'TZH:TZM')) AS dbOSTZ FROM DUAL
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiConn_prepareStmt(0x1a76160) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_getInfo(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_getInfo(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_setFetchArraySize(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_setFetchArraySize(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_setPrefetchRows(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_setPrefetchRows(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_execute(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_execute(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_getQueryInfo(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_getQueryInfo(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiConn_newVar(0x1a76160)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiConn_newVar(0x1a76160) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_define(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_define(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_getQueryInfo(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_getQueryInfo(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiConn_newVar(0x1a76160)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiConn_newVar(0x1a76160) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_define(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_define(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_addRef(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_addRef(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_fetchRows(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_fetchRows(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiVar_release(0x1a89f70)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiVar_release(0x1a89f70) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiVar_release(0x1a8c600)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiVar_release(0x1a8c600) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_release(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_release(0x1a86c40) -> 0
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiStmt_release(0x1a86c40)
ODPI [484590] 2021-10-20 14:12:11.535: fn end dpiStmt_release(0x1a86c40) -> 0
ODPI [484592] 2021-10-20 14:12:11.535: fn start dpiConn_setCallTimeout(0x1a76160)
ODPI [484590] 2021-10-20 14:12:11.535: fn start dpiConn_ping(0x1a76160)
ODPI [484593] 2021-10-20 14:12:11.536: fn start dpiConn_setCallTimeout(0x1a76160)
ODPI [484590] 2021-10-20 14:12:11.536: fn end dpiConn_ping(0x1a76160) -> 0
ODPI [484592] 2021-10-20 14:12:11.536: fn end dpiConn_setCallTimeout(0x1a76160) -> 0
ODPI [484592] 2021-10-20 14:12:11.536: fn start dpiConn_setCallTimeout(0x1a76160)
ODPI [484592] 2021-10-20 14:12:11.536: fn end dpiConn_setCallTimeout(0x1a76160) -> 0
ODPI [484593] 2021-10-20 14:12:11.536: fn end dpiConn_setCallTimeout(0x1a76160) -> 0
ODPI [484593] 2021-10-20 14:12:11.536: fn start dpiConn_setCallTimeout(0x1a76160)
ODPI [484593] 2021-10-20 14:12:11.536: fn end dpiConn_setCallTimeout(0x1a76160) -> 0
ODPI [484593] 2021-10-20 14:12:11.536: fn start dpiConn_release(0x1a76160)
ODPI [484593] 2021-10-20 14:12:11.536: fn end dpiConn_release(0x1a76160) -> 0

Then when I made around 20k request: I'll get something this like this repeatedly

ODPI [541067] 2021-10-20 14:24:45.703: fn start dpiConn_prepareStmt(0x7f95803b74a0)
ODPI [541067] 2021-10-20 14:24:45.703: SQL INSERT INTO batches2( 
		bId, 
		eId,  
		actionType, 
		jsonData, 
		created_at
		)
		VALUES
		(:1,:2,:3,:4,:5)
ODPI [540710] 2021-10-20 14:24:45.704: fn start dpiConn_prepareStmt(0x7f95502399b0)
ODPI [540710] 2021-10-20 14:24:45.704: SQL INSERT INTO batches2( 
		bId, 
		eId,  
		actionType, 
		jsonData, 
		created_at
		)
		VALUES
		(:1,:2,:3,:4,:5)
ODPI [544887] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544597] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544889] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544596] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544890] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [546952] 2021-10-20 14:24:45.704: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544549] 2021-10-20 14:24:45.704: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544549] 2021-10-20 14:24:45.704: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [544600] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [545081] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544549] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544461] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544892] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544603] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544448] 2021-10-20 14:24:45.704: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544448] 2021-10-20 14:24:45.704: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [546951] 2021-10-20 14:24:45.704: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [546951] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544895] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544448] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544601] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [545084] 2021-10-20 14:24:45.704: fn start dpiConn_create(0x1b7ee70)
ODPI [544464] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [544897] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [544468] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [544898] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [545073] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [545082] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [544469] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [546952] 2021-10-20 14:24:45.705: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [546952] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [544901] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [540709] 2021-10-20 14:24:45.705: fn start dpiConn_prepareStmt(0x1f05fc0)
ODPI [540709] 2021-10-20 14:24:45.705: SQL INSERT INTO batches2( 
		bId, 
		eId,  
		actionType, 
		jsonData, 
		created_at
		)
		VALUES
		(:1,:2,:3,:4,:5)
ODPI [544907] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [545086] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [544474] 2021-10-20 14:24:45.705: fn start dpiConn_create(0x1b7ee70)
ODPI [544467] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiStmt_getBindCount(0x7f958a92ff20) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiStmt_getBindNames(0x7f958a92ff20)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiStmt_getBindNames(0x7f958a92ff20) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiConn_newVar(0x7f9588123c90)
ODPI [545394] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [544906] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [545397] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [544604] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [545401] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [544905] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [545714] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiConn_newVar(0x7f9588123c90) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiVar_setFromBytes(0x7f958ab65390)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiVar_setFromBytes(0x7f958ab65390) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiConn_newVar(0x7f9588123c90)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiConn_newVar(0x7f9588123c90) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiVar_setFromBytes(0x7f958ab65490)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiVar_setFromBytes(0x7f958ab65490) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiConn_newVar(0x7f9588123c90)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiConn_newVar(0x7f9588123c90) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiConn_newVar(0x7f9588123c90)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiConn_newVar(0x7f9588123c90) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiVar_setFromBytes(0x7f958ab657b0)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiVar_setFromBytes(0x7f958ab657b0) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiConn_newVar(0x7f9588123c90)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiConn_newVar(0x7f9588123c90) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiVar_setFromBytes(0x7f958ab679e0)
ODPI [540689] 2021-10-20 14:24:45.706: fn end dpiVar_setFromBytes(0x7f958ab679e0) -> 0
ODPI [540689] 2021-10-20 14:24:45.706: fn start dpiStmt_bindByPos(0x7f958a92ff20)
ODPI [544605] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [545713] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [544606] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [545089] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [544602] 2021-10-20 14:24:45.706: fn start dpiConn_create(0x1b7ee70)
ODPI [545092] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [544610] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [544914] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [545404] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [544614] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [544917] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [545407] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [545093] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [544616] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [544920] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [545408] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [544925] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [544618] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [545094] 2021-10-20 14:24:45.707: fn start dpiConn_create(0x1b7ee70)
ODPI [545411] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [544926] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [545099] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [544621] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [544624] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [545409] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [545116] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [544950] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [544627] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [544955] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [545117] 2021-10-20 14:24:45.708: fn start dpiConn_create(0x1b7ee70)
ODPI [544953] 2021-10-20 14:24:45.709: fn start dpiConn_create(0x1b7ee70)
ODPI [544629] 2021-10-20 14:24:45.709: fn start dpiConn_create(0x1b7ee70)
ODPI [545420] 2021-10-20 14:24:45.709: fn start dpiConn_create(0x1b7ee70)
ODPI [546954] 2021-10-20 14:24:45.709: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544628] 2021-10-20 14:24:45.709: fn start dpiConn_create(0x1b7ee70)
ODPI [546954] 2021-10-20 14:24:45.709: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [545419] 2021-10-20 14:24:45.709: fn start dpiConn_create(0x1b7ee70)
ODPI [546954] 2021-10-20 14:24:45.709: fn start dpiConn_create(0x1b7ee70)
ODPI [545126] 2021-10-20 14:24:45.709: fn start dpiConn_create(0x1b7ee70)
ODPI [546953] 2021-10-20 14:24:45.709: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [546953] 2021-10-20 14:24:45.710: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [546953] 2021-10-20 14:24:45.710: fn start dpiConn_create(0x1b7ee70)
ODPI [544630] 2021-10-20 14:24:45.710: fn start dpiConn_create(0x1b7ee70)
ODPI [545128] 2021-10-20 14:24:45.710: fn start dpiConn_create(0x1b7ee70)
ODPI [544958] 2021-10-20 14:24:45.710: fn start dpiConn_create(0x1b7ee70)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiConn_prepareStmt(0x7f957c1791e0) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiStmt_getInfo(0x7f957e57b810)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiStmt_getInfo(0x7f957e57b810) -> 0
ODPI [545428] 2021-10-20 14:24:45.710: fn start dpiConn_create(0x1b7ee70)
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiStmt_getBindCount(0x7f957e57b810)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiStmt_getBindCount(0x7f957e57b810) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiStmt_getBindNames(0x7f957e57b810)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiStmt_getBindNames(0x7f957e57b810) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiConn_newVar(0x7f957c1791e0)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiConn_newVar(0x7f957c1791e0) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiVar_setFromBytes(0x7f957e923290)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiVar_setFromBytes(0x7f957e923290) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiConn_newVar(0x7f957c1791e0)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiConn_newVar(0x7f957c1791e0) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiVar_setFromBytes(0x7f957e923390)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiVar_setFromBytes(0x7f957e923390) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiConn_newVar(0x7f957c1791e0)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiConn_newVar(0x7f957c1791e0) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiConn_newVar(0x7f957c1791e0)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiConn_newVar(0x7f957c1791e0) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiVar_setFromBytes(0x7f957e923690)
ODPI [545088] 2021-10-20 14:24:45.710: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiVar_setFromBytes(0x7f957e923690) -> 0
ODPI [545088] 2021-10-20 14:24:45.710: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiConn_newVar(0x7f957c1791e0)
ODPI [545088] 2021-10-20 14:24:45.710: fn start dpiConn_create(0x1b7ee70)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiConn_newVar(0x7f957c1791e0) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiVar_setFromBytes(0x7f957e923840)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiVar_setFromBytes(0x7f957e923840) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiStmt_bindByPos(0x7f957e57b810)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiStmt_bindByPos(0x7f957e57b810) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiStmt_bindByPos(0x7f957e57b810)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiStmt_bindByPos(0x7f957e57b810) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiStmt_bindByPos(0x7f957e57b810)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiStmt_bindByPos(0x7f957e57b810) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiStmt_bindByPos(0x7f957e57b810)
ODPI [540787] 2021-10-20 14:24:45.710: fn end dpiStmt_bindByPos(0x7f957e57b810) -> 0
ODPI [540787] 2021-10-20 14:24:45.710: fn start dpiStmt_bindByPos(0x7f957e57b810)
ODPI [540787] 2021-10-20 14:24:45.711: fn end dpiStmt_bindByPos(0x7f957e57b810) -> 0
ODPI [540787] 2021-10-20 14:24:45.711: fn start dpiStmt_execute(0x7f957e57b810)
ODPI [545132] 2021-10-20 14:24:45.711: fn start dpiConn_create(0x1b7ee70)
ODPI [544959] 2021-10-20 14:24:45.711: fn start dpiConn_create(0x1b7ee70)
ODPI [544637] 2021-10-20 14:24:45.711: fn start dpiConn_create(0x1b7ee70)
ODPI [545429] 2021-10-20 14:24:45.711: fn start dpiConn_create(0x1b7ee70)
ODPI [544631] 2021-10-20 14:24:45.711: fn start dpiConn_create(0x1b7ee70)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiConn_prepareStmt(0x7f95d80f9240) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiStmt_getInfo(0x7f95da5ade10)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiStmt_getInfo(0x7f95da5ade10) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiStmt_getBindCount(0x7f95da5ade10)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiStmt_getBindCount(0x7f95da5ade10) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiStmt_getBindNames(0x7f95da5ade10)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiStmt_getBindNames(0x7f95da5ade10) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiConn_newVar(0x7f95d80f9240)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiConn_newVar(0x7f95d80f9240) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiVar_setFromBytes(0x7f95da7244b0)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiVar_setFromBytes(0x7f95da7244b0) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiConn_newVar(0x7f95d80f9240)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiConn_newVar(0x7f95d80f9240) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiVar_setFromBytes(0x7f95da7245b0)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiVar_setFromBytes(0x7f95da7245b0) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiConn_newVar(0x7f95d80f9240)
ODPI [545131] 2021-10-20 14:24:45.711: fn start dpiConn_create(0x1b7ee70)
ODPI [541069] 2021-10-20 14:24:45.711: fn start dpiStmt_getInfo(0x7f9589ba0ac0)
ODPI [541069] 2021-10-20 14:24:45.711: fn end dpiStmt_getInfo(0x7f9589ba0ac0) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiConn_newVar(0x7f95d80f9240) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiConn_newVar(0x7f95d80f9240)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiConn_newVar(0x7f95d80f9240) -> 0
ODPI [540882] 2021-10-20 14:24:45.711: fn start dpiVar_setFromBytes(0x7f95da7248b0)
ODPI [540882] 2021-10-20 14:24:45.711: fn end dpiVar_setFromBytes(0x7f95da7248b0) -> 0
ODPI [540882] 2021-10-20 14:24:45.712: fn start dpiConn_newVar(0x7f95d80f9240)
ODPI [540882] 2021-10-20 14:24:45.712: fn end dpiConn_newVar(0x7f95d80f9240) -> 0
ODPI [540882] 2021-10-20 14:24:45.712: fn start dpiVar_setFromBytes(0x7f95da724a10)
ODPI [540882] 2021-10-20 14:24:45.712: fn end dpiVar_setFromBytes(0x7f95da724a10) -> 0
ODPI [540882] 2021-10-20 14:24:45.712: fn start dpiStmt_bindByPos(0x7f95da5ade10)
ODPI [541069] 2021-10-20 14:24:45.712: fn start dpiStmt_getBindCount(0x7f9589ba0ac0)
ODPI [545432] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [545129] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544965] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544641] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544088] 2021-10-20 14:24:45.712: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544088] 2021-10-20 14:24:45.712: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [544088] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [545136] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544967] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544642] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [545436] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [545135] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544645] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544969] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [545438] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544972] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [544646] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [545139] 2021-10-20 14:24:45.712: fn start dpiConn_create(0x1b7ee70)
ODPI [545442] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [544968] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [545443] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [544973] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [544653] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [545440] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [545142] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [544650] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [544975] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [544908] 2021-10-20 14:24:45.713: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544908] 2021-10-20 14:24:45.713: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [544908] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [544657] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [544977] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [545140] 2021-10-20 14:24:45.713: fn start dpiConn_create(0x1b7ee70)
ODPI [545137] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [544666] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [545448] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [544978] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [545153] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [544665] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [544980] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [545718] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [544668] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [545452] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [546955] 2021-10-20 14:24:45.713: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [545451] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [545151] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [544671] 2021-10-20 14:24:45.714: fn start dpiConn_create(0x1b7ee70)
ODPI [545454] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [544672] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [545156] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [546949] 2021-10-20 14:24:45.714: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544982] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [545162] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [544649] 2021-10-20 14:24:45.715: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544649] 2021-10-20 14:24:45.715: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [544649] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [546956] 2021-10-20 14:24:45.714: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [544981] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [545460] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [545155] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [545161] 2021-10-20 14:24:45.715: fn start dpiConn_create(0x1b7ee70)
ODPI [544986] 2021-10-20 14:24:45.716: fn start dpiConn_create(0x1b7ee70)
ODPI [546959] 2021-10-20 14:24:45.716: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [546955] 2021-10-20 14:24:45.716: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [546955] 2021-10-20 14:24:45.716: fn start dpiConn_create(0x1b7ee70)
ODPI [545458] 2021-10-20 14:24:45.716: fn start dpiConn_create(0x1b7ee70)
ODPI [545165] 2021-10-20 14:24:45.716: fn start dpiConn_create(0x1b7ee70)
ODPI [544996] 2021-10-20 14:24:45.716: fn start dpiConn_create(0x1b7ee70)
ODPI [545461] 2021-10-20 14:24:45.716: fn start dpiConn_create(0x1b7ee70)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiConn_prepareStmt(0x7f95681f9c90) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_getInfo(0x7f956a82b870)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiStmt_getInfo(0x7f956a82b870) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_getBindCount(0x7f956a82b870)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiStmt_getBindCount(0x7f956a82b870) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_getBindNames(0x7f956a82b870)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiStmt_getBindNames(0x7f956a82b870) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiConn_newVar(0x7f95681f9c90)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiConn_newVar(0x7f95681f9c90) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiVar_setFromBytes(0x7f956aa57110)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiVar_setFromBytes(0x7f956aa57110) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiConn_newVar(0x7f95681f9c90)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiConn_newVar(0x7f95681f9c90) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiVar_setFromBytes(0x7f956aa57210)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiVar_setFromBytes(0x7f956aa57210) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiConn_newVar(0x7f95681f9c90)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiConn_newVar(0x7f95681f9c90) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiConn_newVar(0x7f95681f9c90)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiConn_newVar(0x7f95681f9c90) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiVar_setFromBytes(0x7f956aa57510)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiVar_setFromBytes(0x7f956aa57510) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiConn_newVar(0x7f95681f9c90)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiConn_newVar(0x7f95681f9c90) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiVar_setFromBytes(0x7f956aa57670)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiVar_setFromBytes(0x7f956aa57670) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_bindByPos(0x7f956a82b870)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiStmt_bindByPos(0x7f956a82b870) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_bindByPos(0x7f956a82b870)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiStmt_bindByPos(0x7f956a82b870) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_bindByPos(0x7f956a82b870)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiStmt_bindByPos(0x7f956a82b870) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_bindByPos(0x7f956a82b870)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiStmt_bindByPos(0x7f956a82b870) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_bindByPos(0x7f956a82b870)
ODPI [540958] 2021-10-20 14:24:45.717: fn end dpiStmt_bindByPos(0x7f956a82b870) -> 0
ODPI [540958] 2021-10-20 14:24:45.717: fn start dpiStmt_execute(0x7f956a82b870)
ODPI [546960] 2021-10-20 14:24:45.716: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [546958] 2021-10-20 14:24:45.716: fn start dpiContext_initConnCreateParams(0x1b7ee70)
ODPI [546956] 2021-10-20 14:24:45.718: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [546949] 2021-10-20 14:24:45.718: fn end dpiContext_initConnCreateParams(0x1b7ee70) -> 0
ODPI [540713] 2021-10-20 14:24:45.718: fn start dpiConn_prepareStmt(0x7f9560273940)
ODPI [544677] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [544997] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [544688] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545000] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545464] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [544687] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545466] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545172] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545176] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545463] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545003] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [544690] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545471] 2021-10-20 14:24:45.718: fn start dpiConn_create(0x1b7ee70)
ODPI [545009] 2021-10-20 14:24:45.719: fn start dpiConn_create(0x1b7ee70)
ODPI [540713] 2021-10-20 14:24:45.719: SQL INSERT INTO batches2( 
		bId, 
		eId,  
		actionType, 
		jsonData, 
		created_at
		)
		VALUES
		(:1,:2,:3,:4,:5)
ODPI [545465] 2021-10-20 14:24:45.719: fn start dpiConn_create(0x1b7ee70)

After that it'll show the stackstrace like before.
Thanks!

@sudarshan12s
Copy link
Collaborator

Doesn't it include other goroutine stacks or any additional error messages?
Is it something to do with limit of GOMAXPROCS and needs tuning? ( runtime.GOMAXPROCS)

@monirz
Copy link
Author

monirz commented Oct 20, 2021

@sudarshan12s Yes, it shows some other goroutine stacks at the end, let me post the other stackstrace. I didn't set the runtime.GOMAXPROCS because as I knew it would use all the cores by default. Also it can handle 60k concurrent request easily if it's not doing anything in Oracle database.

Thanks!

@monirz
Copy link
Author

monirz commented Oct 20, 2021

After it showing the repeated stackstraces like above, it shows some other repeated stackstraces like this:

oroutine 12500 [runnable]:
net/http.(*conn).serve(0xc0298a80a0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12501 [runnable]:
net/http.(*conn).serve(0xc0298a8140, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12502 [runnable]:
net/http.(*conn).serve(0xc0298a81e0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12503 [runnable]:
net/http.(*conn).serve(0xc0298a8280, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12504 [runnable]:
net/http.(*conn).serve(0xc0298a8320, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12505 [runnable]:
net/http.(*conn).serve(0xc0298a83c0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12506 [runnable]:
net/http.(*conn).serve(0xc0298a8460, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12507 [runnable]:
net/http.(*conn).serve(0xc0298a8500, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12508 [runnable]:
net/http.(*conn).serve(0xc0298a85a0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12509 [runnable]:
net/http.(*conn).serve(0xc0298a8640, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12510 [runnable]:
net/http.(*conn).serve(0xc0298a86e0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12511 [runnable]:
net/http.(*conn).serve(0xc0298a8780, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12512 [runnable]:
net/http.(*conn).serve(0xc0298a8820, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12513 [runnable]:
net/http.(*conn).serve(0xc0298a88c0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12514 [runnable]:
net/http.(*conn).serve(0xc0298a8960, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12515 [runnable]:
net/http.(*conn).serve(0xc0298a8a00, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12516 [runnable]:
net/http.(*conn).serve(0xc0298a8aa0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12517 [runnable]:
net/http.(*conn).serve(0xc0298a8b40, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12518 [runnable]:
net/http.(*conn).serve(0xc0298a8be0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12519 [runnable]:
net/http.(*conn).serve(0xc0298a8c80, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12520 [runnable]:
net/http.(*conn).serve(0xc0298a8d20, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12521 [runnable]:
net/http.(*conn).serve(0xc0298a8dc0, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12522 [runnable]:
net/http.(*conn).serve(0xc0298a8e60, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 12523 [runnable]:
net/http.(*conn).serve(0xc0298a8f00, 0x809420, 0xc00011d0e0)
	/usr/local/go/src/net/http/server.go:1797
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b
exit status 2

@monirz
Copy link
Author

monirz commented Oct 20, 2021

Sometimes the stackstrace is different though, like this time I got something like this:

goroutine 11677 [runnable, locked to thread]:
github.com/godror/godror._Cfunc_dpiConn_create(0x252dce0, 0x0, 0x0, 0x0, 0xc000000000, 0x7f6d308b0570, 0xc000000041, 0x0, 0xc02184ebd0, 0xc000806cf0, ...)
	_cgo_gotypes.go:2447 +0x4b
github.com/godror/godror.(*drv).acquireConn.func8.1(0xbc69a0, 0xc022dd8040, 0x0, 0x0, 0xc022dd8048, 0x0, 0x0, 0xc022dd8058, 0xc022dd83c0, 0x0, ...)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/drv.go:571 +0x1a5
github.com/godror/godror.(*drv).acquireConn.func8(0xc022dd7ef8)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/drv.go:571 +0x91
github.com/godror/godror.(*drv).checkExecNoLOT(0xbc69a0, 0xc022dd8180, 0x1, 0xc000806cf0)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/drv.go:262 +0x27
github.com/godror/godror.(*drv).checkExec(0xbc69a0, 0xc022dd8180, 0x7f6d308b0570, 0x0)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/drv.go:256 +0x3e
github.com/godror/godror.(*drv).acquireConn(0xbc69a0, 0xc000212000, 0x79e79f, 0x6, 0x7b25dd, 0x41, 0x79e79f, 0x6, 0x0, 0x0, ...)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/drv.go:564 +0x751
github.com/godror/godror.(*drv).createConn(0xbc69a0, 0xc000212000, 0x79e79f, 0x6, 0x7b25dd, 0x41, 0x79e79f, 0x6, 0x0, 0x0, ...)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/drv.go:383 +0xd8
github.com/godror/godror.(*drv).createConnFromParams(0xbc69a0, 0x79e79f, 0x6, 0x7b25dd, 0x41, 0x79e79f, 0x6, 0x0, 0x0, 0x0, ...)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/drv.go:601 +0x158
github.com/godror/godror.connector.Connect(0xbc69a0, 0x79e79f, 0x6, 0x7b25dd, 0x41, 0x79e79f, 0x6, 0x0, 0x0, 0x0, ...)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/drv.go:1098 +0x73b
database/sql.(*DB).conn(0xc0001871e0, 0x8094e8, 0xc02184c480, 0x41bd01, 0x42308c, 0x7f6f941f6910, 0x30)
	/usr/local/go/src/database/sql/sql.go:1301 +0x184
database/sql.(*DB).exec(0xc0001871e0, 0x8094e8, 0xc02184c480, 0x7b3971, 0x70, 0xc022dd9978, 0x5, 0x5, 0x1, 0x10, ...)
	/usr/local/go/src/database/sql/sql.go:1553 +0x66
database/sql.(*DB).ExecContext(0xc0001871e0, 0x8094e8, 0xc02184c480, 0x7b3971, 0x70, 0xc022dd9978, 0x5, 0x5, 0x10, 0x7f6fc5e421d8, ...)
	/usr/local/go/src/database/sql/sql.go:1535 +0xe5
main.insertIntoBatch(0x809520, 0xc02184c480)
	/root/gocode/src/github.com/monirz/batch/main.go:93 +0x28b
main.CreateBatchHandler(0x808ad0, 0xc021834540, 0xc01490c400)
	/root/gocode/src/github.com/monirz/batch/main.go:64 +0x45
net/http.HandlerFunc.ServeHTTP(0x7b9d60, 0x808ad0, 0xc021834540, 0xc01490c400)
	/usr/local/go/src/net/http/server.go:2049 +0x44
github.com/go-chi/chi.(*Mux).routeHTTP(0xc0000a4060, 0x808ad0, 0xc021834540, 0xc01490c400)
	/root/gocode/pkg/mod/github.com/go-chi/[email protected]/mux.go:436 +0x28b
net/http.HandlerFunc.ServeHTTP(0xc000012020, 0x808ad0, 0xc021834540, 0xc01490c400)
	/usr/local/go/src/net/http/server.go:2049 +0x44
github.com/go-chi/chi.(*Mux).ServeHTTP(0xc0000a4060, 0x808ad0, 0xc021834540, 0xc01490c200)
	/root/gocode/pkg/mod/github.com/go-chi/[email protected]/mux.go:87 +0x331
net/http.serverHandler.ServeHTTP(0xc0000ca000, 0x808ad0, 0xc021834540, 0xc01490c200)
	/usr/local/go/src/net/http/server.go:2867 +0xa3
net/http.(*conn).serve(0xc022db7d60, 0x809520, 0xc021824b80)
	/usr/local/go/src/net/http/server.go:1932 +0x8cd
created by net/http.(*Server).Serve
	/usr/local/go/src/net/http/server.go:2993 +0x39b

goroutine 8709 [semacquire]:
sync.runtime_SemacquireMutex(0xc001e44944, 0x0, 0x0)
	/usr/local/go/src/runtime/sema.go:71 +0x47
sync.(*RWMutex).RLock(...)
	/usr/local/go/src/sync/rwmutex.go:63
github.com/godror/godror.(*conn).ociBreakDone(0xc001e44780, 0x8094e8, 0xc00ee69560, 0xc020323f20)
	/root/gocode/pkg/mod/github.com/godror/[email protected]/conn.go:104 +0x697
created by github.com/godror/godror.(*conn).handleDeadline
	/root/gocode/pkg/mod/github.com/godror/[email protected]/conn.go:97 +0x1de
exit status 2


Note I'm trying with different simplified golang server though where it only inserts into one table.

@tgulacsi
Copy link
Contributor

Is this 20k CONCURRENT connection, or 20k sequential?
Where is the dpiStmt_execute? dpiStmt_close? dpiConn_close?
What is the client (DB calling) code?

@monirz
Copy link
Author

monirz commented Oct 20, 2021

Here is the client I'm trying for generating concurrent request although for simplified server I'm not sending the json data here.
Client link

@monirz
Copy link
Author

monirz commented Oct 20, 2021

And here is the server and SQL table structure I'm trying server

I have set the MinSessions to 20000 though. I was just trying with different numbers.

Thanks!

@monirz
Copy link
Author

monirz commented Oct 20, 2021

Also it don't show these in the output dpiStmt_execute dpiStmt_close dpiConn_close before it showing it started to show the repeated stackstrace.

@monirz
Copy link
Author

monirz commented Oct 20, 2021

request_server.mp4

Here is the partial screen capture of server log.

@tgulacsi
Copy link
Contributor

Why can't you just share that log somewhere?

First, we have to find out where are those resources (dpiStmt, dpiConn) released, or why they aren't.
Please first run a test with DPI_DEBUG_LEVEL=92 and one_request. See what it is like.
Then run it with 2 requests concurrently, then 20, then 200... see when does those resource releases vanish.

A parallel experiment: can you run 20k requests sequentially? How many connections do they use?

@sudarshan12s
Copy link
Collaborator

Few observations, i see:

If you set MinSessions to 20000, DB.Ping() potentially create 20k connections.

so in the logs this dpiPool_create would create potentially 20k connections.
ODPI [484590] 2021-10-20 14:12:11.503: fn start dpiPool_create(0x19d4e70)
ODPI [484590] 2021-10-20 14:12:11.534: fn end dpiPool_create(0x19d4e70) -> 0

In your server program, I see 1000 , increment is made 1. If 20k connections (goroutines) concurrently request connections, increment is small, you can make it little larger or you increase MinSessions. MinSessions are created even before your webserver is on, so the subsequent goroutine requests should just get served with the connections already created in pool .

You mentioned max sessions on server as 6k, this also needs to be increased as concurrent requests are higher.

From traces all goroutines do concurrent connection create and have been assigned a separate OS thread which might be ok .

If MinSessions is high, the goroutines creating new connection shall reduce.

@tgulacsi
Copy link
Contributor

As I see in the video, DPI debug messages intermingle with Go error/stack messages.
As ODPI prints to stderr, move the Go logging to file/stdout and save each separately.

@monirz
Copy link
Author

monirz commented Oct 20, 2021

I was trying around 20k request mostly because that's where it fails and that log is so big I can't trace them all and with small request it does not create the problem but let me share the log for the 1/2 or few requests. Sequentially? I haven't tried for that many request, but will try that.

@monirz
Copy link
Author

monirz commented Oct 20, 2021

This is what I get with one request with DPI_DEBUG_LEVEL=92, nothing else:


ODPI [1574327] 2021-10-20 20:14:23.454: fn start dpiContext_initConnCreateParams(0x2612cf0)
ODPI [1574327] 2021-10-20 20:14:23.454: fn end dpiContext_initConnCreateParams(0x2612cf0) -> 0
ODPI [1574327] 2021-10-20 20:14:23.454: fn start dpiConn_create(0x2612cf0)
ODPI [1574327] 2021-10-20 20:14:23.455: fn end dpiConn_create(0x2612cf0) -> 0
ODPI [1574327] 2021-10-20 20:14:23.455: fn start dpiConn_prepareStmt(0x7f0954048730)
ODPI [1574327] 2021-10-20 20:14:23.455: SQL INSERT INTO batches3( 
		bId, 
		eId,  
		actionType, 
		created_at
		)
		VALUES
		(:1,:2,:3,:4)
ODPI [1574327] 2021-10-20 20:14:23.455: fn end dpiConn_prepareStmt(0x7f0954048730) -> 0
ODPI [1574327] 2021-10-20 20:14:23.455: fn start dpiStmt_getInfo(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.455: fn end dpiStmt_getInfo(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiStmt_getBindCount(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiStmt_getBindCount(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiStmt_getBindNames(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiStmt_getBindNames(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiConn_newVar(0x7f0954048730)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiConn_newVar(0x7f0954048730) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiVar_setFromBytes(0x7f095404ace0)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiVar_setFromBytes(0x7f095404ace0) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiConn_newVar(0x7f0954048730)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiConn_newVar(0x7f0954048730) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiVar_setFromBytes(0x7f095404aec0)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiVar_setFromBytes(0x7f095404aec0) -> 0
ODPI [1574326] 2021-10-20 20:14:23.456: fn start dpiConn_setCallTimeout(0x7f0954048730)
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiConn_newVar(0x7f0954048730)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiConn_newVar(0x7f0954048730) -> 0
ODPI [1574326] 2021-10-20 20:14:23.456: fn end dpiConn_setCallTimeout(0x7f0954048730) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiConn_newVar(0x7f0954048730)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiConn_newVar(0x7f0954048730) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiVar_setFromBytes(0x7f095404b220)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiVar_setFromBytes(0x7f095404b220) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiStmt_bindByPos(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiStmt_bindByPos(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiStmt_bindByPos(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiStmt_bindByPos(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiStmt_bindByPos(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiStmt_bindByPos(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiStmt_bindByPos(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.456: fn end dpiStmt_bindByPos(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.456: fn start dpiStmt_execute(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.635: fn end dpiStmt_execute(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.635: fn start dpiStmt_getRowCount(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.635: fn end dpiStmt_getRowCount(0x7f095404ab90) -> 0
ODPI [1574327] 2021-10-20 20:14:23.636: fn start dpiVar_release(0x7f095404ace0)
ODPI [1574327] 2021-10-20 20:14:23.636: fn end dpiVar_release(0x7f095404ace0) -> 0
ODPI [1574327] 2021-10-20 20:14:23.636: fn start dpiVar_release(0x7f095404aec0)
ODPI [1574327] 2021-10-20 20:14:23.636: fn end dpiVar_release(0x7f095404aec0) -> 0
ODPI [1574327] 2021-10-20 20:14:23.636: fn start dpiVar_release(0x7f095404b0c0)
ODPI [1574327] 2021-10-20 20:14:23.636: fn end dpiVar_release(0x7f095404b0c0) -> 0
ODPI [1574327] 2021-10-20 20:14:23.636: fn start dpiVar_release(0x7f095404b220)
ODPI [1574327] 2021-10-20 20:14:23.636: fn end dpiVar_release(0x7f095404b220) -> 0
ODPI [1574327] 2021-10-20 20:14:23.636: fn start dpiStmt_release(0x7f095404ab90)
ODPI [1574327] 2021-10-20 20:14:23.636: fn end dpiStmt_release(0x7f095404ab90) -> 0
ODPI [1574326] 2021-10-20 20:14:23.636: fn start dpiConn_setCallTimeout(0x7f0954048730)
ODPI [1574326] 2021-10-20 20:14:23.636: fn end dpiConn_setCallTimeout(0x7f0954048730) -> 0
ODPI [1574326] 2021-10-20 20:14:23.636: fn start dpiConn_release(0x7f0954048730)
ODPI [1574326] 2021-10-20 20:14:23.636: fn end dpiConn_release(0x7f0954048730) -> 0

Same repeated result for two request.

@monirz
Copy link
Author

monirz commented Oct 20, 2021

Even with 200 or 1000 request it shows the log as above. And it all get success response.

@monirz
Copy link
Author

monirz commented Oct 20, 2021

@sudarshan12s I basically tried MinSessions with 20000, but 1000 put in the example file mistakenly. I have asked our DBA for increasing the maximum session to at least make it 30k. Should removing the Ping() will make any improvement?

@monirz
Copy link
Author

monirz commented Oct 20, 2021

So, if I remove the db.Ping() part, I will get some error like this with even 1000 requests, but after adding it again 1000 requests works fine, which is a bit a strange to me.

ODPI [1606545] 2021-10-20 21:10:56.933: fn end dpiConn_create(0x7fb23408f0c0) -> -1
ODPI [1606554] 2021-10-20 21:10:56.937: OCI error ORA-24459: OCISessionGet() timed out waiting for pool to create new connections (dpiConn_create / get session)
ODPI [1606554] 2021-10-20 21:10:56.937: fn end dpiConn_create(0x7fb23408f0c0) -> -1
ODPI [1605543] 2021-10-20 21:10:56.942: OCI error ORA-24459: OCISessionGet() timed out waiting for pool to create new connections (dpiConn_create / get session)
ODPI [1605543] 2021-10-20 21:10:56.942: fn end dpiConn_create(0x7fb23408f0c0) -> -1
ODPI [1605572] 2021-10-20 21:10:56.948: OCI error ORA-24459: OCISessionGet() timed out waiting for pool to create new connections (dpiConn_create / get session)
ODPI [1605572] 2021-10-20 21:10:56.948: fn end dpiConn_create(0x7fb23408f0c0) -> -1
ODPI [1606559] 2021-10-20 21:10:56.954: OCI error ORA-24459: OCISessionGet() timed out waiting for pool to create new connections (dpiConn_create / get session)
ODPI [1606559] 2021-10-20 21:10:56.954: fn end dpiConn_create(0x7fb23408f0c0) -> -1

tgulacsi added a commit that referenced this issue Oct 20, 2021
@sudarshan12s
Copy link
Collaborator

So, if I remove the db.Ping() part, I will get some error like this with even 1000 requests, but after adding it again 1000 requests works fine, which is a bit a strange to me.

ODPI [1606545] 2021-10-20 21:10:56.933: fn end dpiConn_create(0x7fb23408f0c0) -> -1
ODPI [1606554] 2021-10-20 21:10:56.937: OCI error ORA-24459: OCISessionGet() timed out waiting for pool to create new connections (dpiConn_create / get session)
ODPI [1606554] 2021-10-20 21:10:56.937: fn end dpiConn_create(0x7fb23408f0c0) -> -1
ODPI [1605543] 2021-10-20 21:10:56.942: OCI error ORA-24459: OCISessionGet() timed out waiting for pool to create new connections (dpiConn_create / get session)
ODPI [1605543] 2021-10-20 21:10:56.942: fn end dpiConn_create(0x7fb23408f0c0) -> -1
ODPI [1605572] 2021-10-20 21:10:56.948: OCI error ORA-24459: OCISessionGet() timed out waiting for pool to create new connections (dpiConn_create / get session)
ODPI [1605572] 2021-10-20 21:10:56.948: fn end dpiConn_create(0x7fb23408f0c0) -> -1
ODPI [1606559] 2021-10-20 21:10:56.954: OCI error ORA-24459: OCISessionGet() timed out waiting for pool to create new connections (dpiConn_create / get session)
ODPI [1606559] 2021-10-20 21:10:56.954: fn end dpiConn_create(0x7fb23408f0c0) -> -1

keep the db.Ping, it basically causes pool to be created as part of single thread. if multiple goroutines try to create a pool, it can cause above. So db.ping before webserver start looks good.

@tgulacsi
Copy link
Contributor

PTAL TestConcurrency in z_conn_test.go of 2744bd2

Tweak it for your environment (either use it with env GODROR_TEST_DSN="..." go test -run=Concurrency -v, or just the innards), and see what's the most number of concurrency you can achieve.

For my free Oracle ADB instance, it has inserted 8192 rows in 21s, using 16 sessions - concurrency was 8192.

One difference is that I have poolWaitTimeout=5s while you have 0.
For description, see https://oracle.github.io/odpi/doc/structs/dpiPoolCreateParams.html#dpipoolcreateparams

AFAIK with 0 it won't wait for a connection to be available.

@monirz
Copy link
Author

monirz commented Oct 20, 2021

Okay, I'll have to dig down to it. I'll come back to you soon.

@tgulacsi
Copy link
Contributor

I can reproduce something similar when creating a separate connection pool to the same DB:

fatal error: unexpected signal during runtime execution
fatal error: unexpected signal during runtime execution
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x7f4df4f38e31]

runtime stack:
runtime.throw({0x78ffa0, 0x7f4d00000070})
        /usr/local/go/src/runtime/panic.go:1198 +0x71
runtime.sigpanic()
        /usr/local/go/src/runtime/signal_unix.go:719 +0x396

goroutine 19062 [syscall, locked to thread]:
runtime.cgocall(0x6ffd20, 0xc00823a3e8)
        /usr/local/go/src/runtime/cgocall.go:156 +0x5c fp=0xc00823a3c0 sp=0xc00823a388 pc=0x411d3c
github.com/godror/godror._Cfunc_dpiConn_create(0x1908a40, 0x7f4e10f28340, 0x4, 0x7f4de50a8640, 0x14, 0x7f4de50a8660, 0x13, 0xc0033c08c0, 0xc007c7eb40, 0xc0000965a0)
        _cgo_gotypes.go:2447 +0x4c fp=0xc00823a3e8 sp=0xc00823a3c0 pc=0x5a28ac
github.com/godror/godror.(*drv).acquireConn.func8.1(0xc000033800, 0xc00823a4d0, {0xc0000a008c, 0x4}, 0x10000c00823a508, {0xc0000c6000, 0x14}, 0x8, 0x7f4e3ca08f18, 0xc0033c08c0, ...)
        /home/gthomas/src/github.com/godror/godror/drv.go:571 +0x159 fp=0xc00823a478 sp=0xc00823a3e8 pc=0x5bd1b9

I can toggle it by leaving db.MaxOpenConns as is (unlimited) or limiting it to the same as PoolParams.MaxSessions.

See line line 40 in z_conc_test.go of f3f72c3 !

@monirz
Copy link
Author

monirz commented Oct 20, 2021

Are you just it running from the test or trying with a client code with similar approach? I have ran the test and passed but did not see any concurrency number:

--- PASS: TestConcurrency (42.03s)
PASS
ok  	github.com/godror/godror	42.146s

It's on my local machine though, I'm gonna try it on the vm now. Also will be trying those parameters accordingly. And see what happens.

@tgulacsi
Copy link
Contributor

tgulacsi commented Oct 20, 2021 via email

@monirz
Copy link
Author

monirz commented Oct 20, 2021

So running the test with this command env GODROR_CONC_NO_LIMIT=1 GODROR_TEST_DSN="..." go test -run=Concurrency I'm getting test failed and got the error like this:

z_conc_test.go:83: user="" ConnectString="..." stats=busy=16 open=16 max=16 maxLifetime=5m0s timeout=1m0s waitTimeout=5s params={authMode:0 connectionClass:0x7fcdd4048320 connectionClassLength:13 purity:0 newPassword:<nil> newPasswordLength:0 appContext:<nil> numAppContext:0 externalAuth:0 externalHandle:<nil> pool:0x7fcda8047760 tag:<nil> tagLength:0 matchAnyTag:0 outTag:<nil> outTagLength:0 outTagFound:0 shardingKeyColumns:<nil> numShardingKeyColumns:0 superShardingKeyColumns:<nil> numSuperShardingKeyColumns:0 outNewSession:0}: ORA-24459: OCISessionGet() timed out waiting for pool to create new connections

What does that indicate?

@tgulacsi
Copy link
Contributor

Strange. With GODROR_CONC_NO_LIMIT=1 I get sigsegv, without it the test passes.

Either way, try setting db.SetMaxConns to something not higher than poolMaxSessions.
I think this is a signal handling error somewhere, but this should protect from it.

@monirz
Copy link
Author

monirz commented Oct 20, 2021

Okay, so with MaxSession and MinSession set to 100 I have been able to get to pretty close to 19k concurrent requests. No server side crashing though but got some connection reset by peer from client side. That's different though.
Successful request: 18723
And got 277 request read: connection reset by peer. So the problem was apparently setting the MaxSession high, even with 1000 it'll throw the error or stackstrace. Still need to dig a little more. And will come back with final result.

        P.PoolParams.SessionIncrement = 30
        P.PoolParams.MaxSessions = 100
        P.PoolParams.MinSessions = 100

        P.PoolParams.WaitTimeout = time.Second * 5

       
        // fmt.Println(P.StringWithPassword())
        log.Println(P)
        DB = sql.OpenDB(godror.NewConnector(P))

        if err := DB.Ping(); err != nil {
                log.Println(err)
                log.Fatal(err, " dsn: ")
        }

        DB.SetMaxIdleConns(P.PoolParams.MinSessions)
        DB.SetMaxOpenConns(P.PoolParams.MaxSessions)

@tgulacsi
Copy link
Contributor

DB.SetMaxIdleConns(P.PoolParams.MinSessions) is disputable.
DB.SetMaxIdleConns(0) puts all the pooling into Oracle side, with higher it allows Go to cache some connections.

Although for high concurrency, I'd set it around the average (mininum?) number of concurrent requests.

By tuning it, you may be able to gain latency, but release session back to Oracle less often.

@sudarshan12s
Copy link
Collaborator

Okay, so with MaxSession and MinSession set to 100 I have been able to get to pretty close to 19k concurrent requests. No server side crashing though but got some connection reset by peer from client side. That's different though. Successful request: 18723 And got 277 request read: connection reset by peer. So the problem was apparently setting the MaxSession high, even with 1000 it'll throw the error or stackstrace. Still need to dig a little more. And will come back with final result.

        P.PoolParams.SessionIncrement = 30
        P.PoolParams.MaxSessions = 100
        P.PoolParams.MinSessions = 100

        P.PoolParams.WaitTimeout = time.Second * 5

       
        // fmt.Println(P.StringWithPassword())
        log.Println(P)
        DB = sql.OpenDB(godror.NewConnector(P))

        if err := DB.Ping(); err != nil {
                log.Println(err)
                log.Fatal(err, " dsn: ")
        }

        DB.SetMaxIdleConns(P.PoolParams.MinSessions)
        DB.SetMaxOpenConns(P.PoolParams.MaxSessions)

Adding some details on the parameters.
when DB.Ping is done, P.PoolParams.MinSessions number of connections are created in the pool. P.PoolParams.MaxSessions, P.PoolParams.SessionIncrement are used at runtime after pool creation for expansion. P.PoolParams.MinSessions is used at runtime for shrinking the pool till MinSessions.

when DB.SetMaxOpenConns is higher than the current connections in the pool, the goroutine requests wait till the pool expansion is done based on P.PoolParams.SessionIncrement limited by P.PoolParams.MaxSessions.

So to avoid expansion of pool after pool creation, we can provide higher P.PoolParams.MinSessions but this is the size of pool retained at runtime.

poolWaitTimeout - the time waited to get a new connection from pool. Default is 30s. It can cause ORA-24459 if all goroutines have taken up the connections and are busy and pool is expanding for the new goroutine request.

poolSessionTimeout - used to terminate idle connections. Default is 5 Min.

@sudarshan12s
Copy link
Collaborator

Okay, so with MaxSession and MinSession set to 100 I have been able to get to pretty close to 19k concurrent requests. No server side crashing though but got some connection reset by peer from client side. That's different though. Successful request: 18723 And got 277 request read: connection reset by peer. So the problem was apparently setting the MaxSession high, even with 1000 it'll throw the error or stackstrace. Still need to dig a little more. And will come back with final result.

        P.PoolParams.SessionIncrement = 30
        P.PoolParams.MaxSessions = 100
        P.PoolParams.MinSessions = 100

        P.PoolParams.WaitTimeout = time.Second * 5

       
        // fmt.Println(P.StringWithPassword())
        log.Println(P)
        DB = sql.OpenDB(godror.NewConnector(P))

        if err := DB.Ping(); err != nil {
                log.Println(err)
                log.Fatal(err, " dsn: ")
        }

        DB.SetMaxIdleConns(P.PoolParams.MinSessions)
        DB.SetMaxOpenConns(P.PoolParams.MaxSessions)

I think you are not seeing SIGSEGV . Still if you can upload entire logs to somewhere like, https://gist.github.com/ it helps identify that termination reason.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants