*sql.DB is slow when shared by goroutines?

[shouich...@gmail.com]

Hi gophers,

I wrote a simple benchmark (https://gist.github.com/shouichi/35a840fd3b5357fa7193) of database/sql.

It simply selects all users (about 10K rows) from the users table from multiple goroutines.

The problem is that increasing the number of goroutines makes selecting almost linearly slow (the result is attached).

I have no idea what is causing this problem.

Shouichi,

Thanks

[Robert Melton]

Wouldn't increasing the number of goroutines increase the concurrent load on the database?  How did you separate the "go performance issue" from the "postgresql performance issue"?  Additionally, I think append would cause some allocation cost, and GC cost.

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--
Robert Melton | http://robertmelton.com

[Matt Silverlock]

Alongside the use of append (which will no doubt require lots of resizing), there's also your Postgres configuration: max connections being the big one in a simple case like this.

[shouich...@gmail.com]

I inspected using runtime package and found that the most time consuming part was "rows.Next()" line, which doesn't make any sense for me.

[Konstantin Khomoutov]

On Tue, 24 Jun 2014 06:28:41 -0700 (PDT)
shouich...@gmail.com wrote:

> I inspected using runtime package and found that the most time
> consuming part was "rows.Next()" line, which doesn't make any sense
> for me.

*sql.DB should use a lock internally to serialize all access to it.
To cite the documentation:

> DB is a database handle. It's safe for concurrent use by multiple
> goroutines.

Might this be the reason for the slowdown you're observing?

[shouich...@gmail.com]

On Tuesday, June 24, 2014 10:25:56 PM UTC+9, Matt Silverlock wrote:

Alongside the use of append (which will no doubt require lots of resizing), there's also your Postgres configuration: max connections being the big one in a simple case like this.

Do you know better way not using append? I want to pre allocate array first and fill it later but the problem is there is no way to know the length of rows such as rows.Count(). About postgres config, the max connection is set 1000, so postgres connection size shouldn't be a problem.

 

[shouich...@gmail.com]

This is a part of output from pprof tool. https://gist.github.com/65ab6919c6df21c2821b

The question is why rows.Next() is the slowest part, rather than db.Query().

[Robert Melton]

On Tue, Jun 24, 2014 at 10:02 AM, <shouich...@gmail.com> wrote:

On Tuesday, June 24, 2014 10:39:10 PM UTC+9, Konstantin Khomoutov wrote:

On Tue, 24 Jun 2014 06:28:41 -0700 (PDT)

shouich...@gmail.com wrote:

> I inspected using runtime package and found that the most time
> consuming part was "rows.Next()" line, which doesn't make any sense
> for me

I assume you have GOMAXPROCS environmental variable setup?  If not, try adding runtime.GOMAXPROCS(runtime.NumCPU()*2) ... or similar and see how that changes the performance and pinch points.

[Daniel Theophanes]

*sql.DB should not serialize all access to it. it should safely hand out database connections, regardless of the method used.

The database/sql package is designed to read the next row into memory in rows.Next(), so it is then that it is waiting for network and parsing the incoming data stream.

DB isn't a "database handle", it is a connection pool. The name is a constant source of confusion. When you run a query, the first thing it does is to either hand out an existing connection or open a new one.

Honestly, that graph you attached is troubling. Can you state what version of Go you are running and what your GOMAXPROCS is?

-Daniel

[shouich...@gmail.com]

Setting runtime.GOMAXPROCS(runtime.NumCPU()*2) makes it much slower.

[shouich...@gmail.com]

> Can you state what version of Go you are running and what your GOMAXPROCS is?

The go version is go1.3 linux/amd64. GOMAXPROCS is not set neither by runtime.GOMAXPROCS() nor env var.

[Konstantin Khomoutov]

On Tue, 24 Jun 2014 07:02:48 -0700 (PDT)

shouich...@gmail.com wrote:

> > > I inspected using runtime package and found that the most time
> > > consuming part was "rows.Next()" line, which doesn't make any
> > > sense for me.
> >
> > *sql.DB should use a lock internally to serialize all access to it.
> > To cite the documentation:
> >
> > > DB is a database handle. It's safe for concurrent use by multiple
> > > goroutines.
> >
> > Might this be the reason for the slowdown you're observing?
> >
>
> This is a part of output from pprof tool.
> https://gist.github.com/65ab6919c6df21c2821b
> The question is why rows.Next() is the slowest part, rather than
> db.Query().

Calling db.Query() might just initiate the fetching of data when
rows.Next() performs the actual heavy lifting: reads from the
connection, parses the data, analyzes it and assigns to the caller's
variables.

[Robert Melton]

On Tue, Jun 24, 2014 at 10:19 AM, <shouich...@gmail.com> wrote:

Setting runtime.GOMAXPROCS(runtime.NumCPU()*2) makes it much slower.

How did the performance look from the PostgreSQL side?  The pg_stat_* stuff?  How does htop and iostat look?  I have no evidence except my own experience, but we do no see linear slowdown on similar performance benchmarks (we have VERY large tables, one in the billions of rows).  I suspect (guess) that something bad is happening on the PostgreSQL side... that got worse as you increased the true concurrency.  If you poke around, I bet you will find that Go is patiently blocking waiting for PostgreSQL to respond to it... if that is the case, start your investigation on the big 6 config tweaks: autovacuum_naptime, checkpoint_segments, effective_cache_size, shared_buffers, wal_buffers, work_mem. 

Could you tell us more about the users table, or better yet, make a fake version of it to test on that you could share?  Just filled with random noise would be fine, as long as it shows the same performance problems as your real data (as close to mimicking the exact real data problem as possible).

[shouich...@gmail.com]

Well, I'm not a postgres expert so I re-install postgres 9.3 to make sure that I'm not doing stupid but still slow. Can you tell me exactly what config to change?

This is the dump of target database. https://gist.github.com/shouichi/4f60f52ba8381a7a9d9e

[Robert Melton]

On Tue, Jun 24, 2014 at 11:53 AM, <shouich...@gmail.com> wrote:

Well, I'm not a postgres expert so I re-install postgres 9.3 to make sure that I'm not doing stupid but still slow. Can you tell me exactly what config to change?

This is the dump of target database. https://gist.github.com/shouichi/4f60f52ba8381a7a9d9e

That will be a huge help.  I won't be able to really give it a look until tonight, but I suspect I will be able to track it down.  Could you post your current postgresql config as well (as the last piece of the puzzle) and I promise I will give it a look over later tonight.  

[voidlogic]

Yes, even if you don't know what rows.Count(), if you know what is would typically be you can replace:

users := []user{}
with:

const estUserc = 128	
users := make([]user, 0, estUserc)

Alot of the gain here comes from not doing all the initial grow operations, the closer estUserc is to reality the better you will do.

[shouich...@gmail.com]

This is postgres.conf. https://gist.github.com/shouichi/573a53b22844bf745866

Robert, I really appreciate your kindness and help :)

[Dave Cheney]

Please use the block profile mode of the build in profiler. You can use my profile package to automate this, github.com/davecheney/profile. When you get a profile post the output from the svg mode, the cause of the contention will be obvious. I suspect it will be the fact that each call to run(db) will (try to) spawn a new database connection.

[Daniel Theophanes]

Good point.

It would be interesting to re-run the benchmark, but first set:

db.SetMaxIdleConns(n)

db.SetMaxOpenConns(n)

[Henrik Johansson]

I am quite a noob with the profiler but it seems like the Next call takes up a lot of time.

➜  pgbench  go tool pprof ./pgbench /tmp/profile436744940/cpu.pprof

Possible precedence issue with control flow operator at /usr/lib/go/pkg/tool/linux_amd64/pprof line 3008.

Welcome to pprof!  For help, type 'help'.

(pprof) top10

Total: 58 samples

      10  17.2%  17.2%       10  17.2% runtime.MSpan_Sweep

       5   8.6%  25.9%       24  41.4% runtime.mallocgc

       4   6.9%  32.8%        4   6.9% settype

       3   5.2%  37.9%        3   5.2% runtime.markscan

       3   5.2%  43.1%       16  27.6% runtime.new

       2   3.4%  46.6%        5   8.6% bufio.(*Reader).Read

       2   3.4%  50.0%       27  46.6% database/sql.(*Rows).Next

       2   3.4%  53.4%        5   8.6% database/sql.(*Rows).Scan

       2   3.4%  56.9%        3   5.2% database/sql.convertAssign

       2   3.4%  60.3%       25  43.1% github.com/lib/pq.(*rows).Next

Does not seem strange at all since each goroutine reads the entire table.

I generated 10000 rows to get some measurements and indeed it varies heavily depending on row count as well.

/ Henrik

--

[Henrik Johansson]

Dave, your profiling util rox!

/ Henrik

[Henrik Johansson]

This is with the block profile. Does it mean there is contention on the connectionOpener?

➜  pgbench  go tool pprof ./pgbench /tmp/profile086424651/block.pprof

Possible precedence issue with control flow operator at /usr/lib/go/pkg/tool/linux_amd64/pprof line 3008.

Welcome to pprof!  For help, type 'help'.

(pprof) top10

Total: 0.933 seconds

   0.682  73.1%  73.1%    0.682  73.1% runtime.chansend1

   0.191  20.4%  93.5%    0.191  20.4% runtime.chanrecv2

   0.061   6.5% 100.0%    0.061   6.5% runtime.chanrecv1

   0.000   0.0% 100.0%    0.000   0.0% sync.(*Mutex).Lock

   0.000   0.0% 100.0%    0.000   0.0% database/sql.(*DB).Query

   0.000   0.0% 100.0%    0.000   0.0% database/sql.(*DB).conn

   0.000   0.0% 100.0%    0.191  20.4% database/sql.(*DB).connectionOpener

   0.000   0.0% 100.0%    0.000   0.0% database/sql.(*DB).putConn

   0.000   0.0% 100.0%    0.000   0.0% database/sql.(*DB).query

   0.000   0.0% 100.0%    0.000   0.0% database/sql.(*Rows).Close

I removed logging since it amounted to noise (I hope).

[Tad Glines]

It seems likely, as Dave suggests, that the bulk of the cost of each call to run() is going to be in the connection establishment.

A quick way to determine this is to repeat the two loops in main(), but only record the times in the second loop set.

Connection establishment in PostgreSQL is (in my experience) typically in the 100's of milliseconds, but query execution can be in the low 10's of milliseconds (at least for cached results).

-Tad

[Henrik Johansson]

Maybe but even with limiting the number of connections the performance continues to degrade as the program continues. Each goroutine takes longer to complete.

While it can make sense I kind of imagined that some sort of steady state would establish itself if the number of connections was limited.

[Tad Glines]

There is a single go routine running the connection opener (See line 442 in http://golang.org/src/pkg/database/sql/sql.go). If the cost of a query is dominated by the cost to open a connection (as I have suggested in this case) then the time for each go routine to get it's results will grow linearly with the number of go routines.

The execution of the go routines are effectively serialized due to the way the connection opener works.

In order to eliminate the connection establishment cost from the timing results it will be necessary to run the loops twice. The first time to establish the connections, the second time to get the timing results. It will also be necessary to db.SetMaxIdleConns(n) (as Danial suggested) or most of the connections will get closed between the two loops.

[Dave Cheney]

go tool pprof --web./pgbench /tmp/profile086424651/block.pprof

And make the result available somewhere, that will show the problem.

[Daniel Theophanes]

I'm curious if you still see the same behavior if using:

"bitbucket.org/kardianos/rdb"

_ "bitbucket.org/kardianos/rdb/pg"

The interface and connection string will be slightly different, but it has a different pool implementation.

(Note, the pg driver is still incomplete, but it should have enough there to select a string I think.)

--
You received this message because you are subscribed to a topic in the Google Groups "golang-nuts" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/golang-nuts/0HW4T81tw1Q/unsubscribe.
To unsubscribe from this group and all its topics, send an email to golang-nuts...@googlegroups.com.

[ma...@joh.to]

Hi all, Shouichi,

I've changed the original benchmark slightly to make sure connection establishment overhead is not a problem, but I'm still observing a significant slowdown when using more than one goroutine.  pprof suggests that a lot of the time is spent in runtime.new(), allocating and garbage collecting memory for pq's conn.recvMessage().  I've hacked on the driver a bit to avoid some of the allocations and I can shave off ~17% of the run time.  I can drop ~17% further by avoiding allocations inside the test case itself, but it's still nowhere close to linear scaling.  I'm not sure how much blame I would put on my postgres setup (probably a non-zero amount), but it seems that there's a number of things that could be on the Go side here as well.

.marko

[Matt Silverlock]

As an aside, it would be fantastic if you could submit these changes as a PR to the lib/pq project.

[shouich...@gmail.com]

I tried using MySQL instead of PostgreSQL and got linear slowdown. There must be a problem with go side.

[shouich...@gmail.com]

Uploaded svg from go tool pprof. The slowest part is ExternalCode (which I don't understand).

https://gist.github.com/07ab210d73bba8b0ad16