Very slow on Windows

[brianoh]

Very slow on Windows

[fdr]

Unfortunately I have zero windows machines to work with and am not particularly interested in going out of my way to get any, so any fix or diagnosis will have to come from someone who has access to and interest in pq on Windows.

I'm willing to help as much as I can modulo access to those platforms, so I suggest dumping the .svg pprof can generate. Other kinds of information are helpful, if you have any that you think is relevant....

[brianoh]

Please note: I have used localhost for all testing. When internet is disconnected (ie. no broadband connected) on Windows, it runs much faster. "go test" takes 3 seconds compared to 0.321 seconds on Ubuntu, but much faster than the 39 seconds that it takes on Windows with the broadband connected. On Ubuntu it makes no difference to times whether internet is connected or not.

[fdr]

Clearly some kind of resolution is not very good on Windows for go test, but I'm a bit more concerned about a single SELECT seeing performance degradation: is that true in steady-state, or are you wrapping that into a test that is also testing startup-time?

All signs suggest that Windows is somehow configured to do something excessively expensive to resolve whatever address pq is using.

[brianoh]

I've done some more tests so as to attempt to isolate what is causing the slowness. They are as follows:

-----------------------------------------------------------------------------------------------------------

Let me know if you want me to send/post the minimalist test program. It's < 100 lines.

-----------------------------------------------------------------------------------------------------------------

======= Test run 1 using testdb001.go – Internet disconnected ==============
About to do a test select (sample 1) from customer: SELECT iId FROM customer
ORDER BY random() LIMIT 1
Elapsed Time = 58.0033ms
About to do a test select from customer: SELECT iId FROM customer
ORDER BY iId DESC LIMIT 1
Elapsed Time = 41.0024ms

======= Test run 2 using testdb001.go – Internet is connected ==============
About to do a test select (sample 1) from customer: SELECT iId FROM customer
ORDER BY random() LIMIT 1
Elapsed Time = 2.3181326s
About to do a test select from customer: SELECT iId FROM customer
ORDER BY iId DESC LIMIT 1
Elapsed Time = 2.3051319s

============= Test 3 – Using psql with internet disconnected =========
bankdb1=# SELECT count(*) FROM customer;
count
-------
156
(1 row) Time: 1.961 ms
bankdb1=# SELECT iId FROM customer ORDER BY random() LIMIT 1;
iid
--------
100231
(1 row) Time: 2.766 ms
bankdb1=# SELECT iId FROM customer ORDER BY iId DESC LIMIT 1;
iid
-------- 100252 (1 row) Time: 2.192 ms

========= Test run 4 – psql with internet connected.
bankdb1=# SELECT iId FROM customer ORDER BY random() LIMIT 1;
iid
--------
100252 (1 row) Time: 1.485 ms

bankdb1=# SELECT iId FROM customer ORDER BY iId DESC LIMIT 1;

iid

--------

100252 (1 row) Time: 0.755 ms

bankdb1=# SELECT count(*) FROM customer;

count

-------

156 (1 row) Time: 1.705 ms

======== End of test run 4 ==========

=========== Select using psql indicating the size of the table (customer) =======
The following gives an idea as to the size of the table :
bankdb1=# select * from customer;
snamefamily | snamegiven1 | snamegiven2 | snamegiven3 | snametitle | iid
-------------+-------------+-------------+-------------+------------+--------
abercrombie | ladislav | viggo | | mr | 100195
abercrombie | ladislav | viggo | | mr | 100196
………………..
………………..
Carpenter | Waleter | Peter | | Prof. | 100241
carter | robert | william | | MR | 100252
(156 rows) Time: 2.573 ms

[brianoh]

-------------------------------------------------------

Simple test program is below.

============================

--------------------------------------------------------

package main

//********************************************************************************//
// Test pgsql Database using pg for some simple tests showing times //
//*******************************************************************************//

import (
    "database/sql"
    "fmt"
    _ "github.com/bmizerany/pq"
    "os"
    "time"
)

var pogDbConn *sql.DB // pq-postgresql connection

func main() {
    fmt.Println("testdb001 - small test on postgresql and pq")

    fDbConnect() // connect to db

    defer pogDbConn.Close()

    fDbSelects() // run test selects

    fmt.Println("All tests completed")
}

func fDbConnect() { // connect to db

    var oOsError error = nil

    fmt.Printf("\nAbout to connect to database\n")

    tmeStart := time.Now()

    pogDbConn, oOsError = sql.Open("postgres",
        "user=admin dbname=bankdb1 password=admin sslmode=disable")

    tmeElapsed := time.Since(tmeStart)
    fmt.Printf("Elapsed Time to connect to database = %ss\n", tmeElapsed)

    if oOsError != nil {
        fmt.Printf("Unable to open bankdb1. Error = %s\n", oOsError)
        os.Exit(1)
    }

    println("Connected to database")
}

func fDbSelects() { // Do a mini-test on database using Selects //  
    var oOsError error = nil

    var sSql string = "SELECT iId FROM customer ORDER BY random() LIMIT 1"

    fmt.Printf("About to do a test select (sample 1) from customer:\n %s \n", sSql)

    tmeStart := time.Now()

    _, oOsError = pogDbConn.Query(sSql) // Query database

    tmeElapsed := time.Since(tmeStart)
    fmt.Printf("Time elapsed = %s\n", tmeElapsed)

    if oOsError != nil {
        fmt.Printf(
            "SELECT of customer failed. SQL = "+sSql+".  Error = %s\n", oOsError)
        os.Exit(1)
    }

    sSql = "SELECT iId FROM customer ORDER BY iId DESC LIMIT 1"

    fmt.Printf("About to do a test select from customer: \n %s \n", sSql)

    tmeStart = time.Now()

    _, oOsError = pogDbConn.Query(sSql) // Query database

    tmeElapsed = time.Since(tmeStart)
    fmt.Printf("Elapsed Time = %s\n", tmeElapsed)

    if oOsError != nil {
        fmt.Printf(
            "SELECT of customer failed. SQL = \n%s\n.  Error = %s\n", sSql, oOsError)
        os.Exit(1)
    }

    fmt.Println("Test Selects completed")
}

[fdr]

Well, not to string you along, but just to be clear that I do not have access to Windows. Nevertheless, I surmise your benchmarks would be more useful if they were in the Go testing package BenchmarkXXX format, if possible. Basically, I'd like to be able to run them on Linux, also.

[verokarhu]

I ran into this issue as well. After some testing I noticed that go test runs very slowly (over 70 seconds) when connecting to the windows postgresql server through loopback/localhost, same machine but through the lan ip and separate windows client over the lan. However, when I setup a linux virtualbox and ran the go test from there (still connecting to the windows server) the test ran in under a second.

It would also seem that the more network interfaces are enabled when I run the test through localhost the slower it gets. I gave up on trying to figure it out for now, posting this in case someone else finds it useful.

[fdr]

That is very good information; it sounds like a resource leak if things get
slower over time; I wonder if connections are being cleaned up properly.

It wasn't cost l clear to me if you tried modifying the test to use IP
addresses instead of symbolic hostnames; have you tried that? If not,
would you be so kind as to?

[verokarhu]

Ah, yes. I forgot to mention that all the tests used IP addresses, which was probably the first thing I should have mentioned since you were speculating earlier about address resolution. :)

[brianoh]

Hi, as I said in my initial post on this problem:

"Running "GO test" takes 0.321 seconds (Linux), and it takes 39.287 seconds (Windows). Subsequent runs on Linux get it just under 0.100 seconds, and on Windows just under 39 seconds."

I can do additional testing if it will help, however I think that the timings from the inbuilt test environment (and also my illustrated tests) tell the story to a large extent There is obviously a problem somewhere. It may be configuration, and it may be a bug. If it's a bug, it would be good to fix it, likewise with the environment.

[fdr]

Well, again, I don't have a Windows machine, and I'm not really inclined to go to the trouble of getting one, so while I'm ready to dispense any insights I can offer they fall short of me making any attempt to reproduce this.

What I'd recommend doing is trying to run the profiler, or instrumenting pq to figure out what is taking so much time.

[sashanv]

Sorry, bad english.
I also have this problem on Windows 7. After connect to DB, first select performed ~36 sec, subsequent 0.2 ms. The delay only on the first call to DB.

[idigger]

I found this problem is caused by the calling function user.Current(in conn.go) -> syscall.TranslateAccountName(in lookup_windows.go) -> TranslateName(in security_windows.go),
Call the function TranslatedName very slow when the Active Directory Domain Services did not set.

[kisielk]

As far as I can tell that function is only called in Open(), so would that not be just a one-time cost when opening a new connection to the server?

The test does this often which would be why the performance there is slow...

[jeucal]

I meet the same problem. Seems that the first(and second) query too slow, and then the rest normal.

[brianoh]

This problem remains a problem. Although the initial Selects etc. are slower than subsequent ones, it is only a marginal difference in most cases, and that is not the problem (warming up). What I am talking about is constant slowness while the internet is connected via broadband using Ethernet even when accessing Postgres locally through Windows Console in a Go program. It appears to me that Go uses Ipv4 while psql and PgAdmin3 both appear to use Ipv6. When the internet is connected and either running Go directly from the Windows Console or from an Internet Connection over localhost to a Go server, the problem remains. It is very slow by a factor of about 40 compared to when the internet is not connected.

I don't experience this problem using Mysql and go-sql-driver / mysql. With this pq Postgres driver without the broadband internet connected, performance is OK with a marginal slowness before it warms-up (ie. initially). I have tested with Firewall disabled and anti-virus disabled, and problem remains when internet is connected. While I could possibly switch to Linux, I chose Postgres because it works on both.

Ran into this problem when using Go, PostgreSQL plus this driver on a variety of platforms - Linux, Mac, and Windows. I can reproduce this problem exactly as described - go test is about 38 seconds on any Windows box, and about 0.125 seconds on an older Linux machine.

Reading through this code was very instructive - it's clean, quite well written and easy to follow. The problem was tracked down to conn.go, line 61 to line 64. On every database open, the code is calling the OS function user.Current() to get the name of the current user. On my Windows machines this appears to take about 2.3 seconds for every call, which accounts for 100% of the slowdown witnessed in this thread. There is very little reason to extract the user name from the environment - it's a convenience feature with odd side effects (as mentioned in the code comments) if you change environments but rely on this feature to extract your previous user name.

There are a few solutions - you could extract the user name in the file's init() incurring the slow 2.3 second call only once in your program; or get rid of this bit of code entirely and ensure that the user name (if needed) is setup during your Open call parameters (as it probably should be).

Removing this bit of code breaks the tests as they are written - the solution is to pass the user name into the Open call in the tests themselves if you decide to remove the user.Current() call. My vote for what it's worth is to remove the user.Current() call entirely, removing the problem in Windows and ensuring the user of the library makes the safer and clearer user= statement in their open call.

Whomever wrote and maintains this library - thanks. It's been quite useful for my current project, and was very instructive to read through.

[kisielk]

Wasn't this mostly fixed by #104 ?

Apparently this package which was located at bmizerany/pq as been moved over to this location, lib/pq. The golang 1.1 library wiki points to the correct spot. Even though I commented in this forum, I hadn't noticed until recently. I had been using the bmizerany version. If possible, updating the readme on the bmizerany page (or getting rid of it entirely) would be helpful to anyone else who had been using this package pre-Go1.1.

The slow user.Current() call appears to be some sort of Windows domain lookup timeout process, and will be dependent on the user's login and network setup.

If the user name is set, then fix #104 prevents the slow (on Windows only) user.Current() call from being executed at all, and things run fine. However, the call is still in the Open() func, meaning it gets called fairly often depending on what you are doing. Running go test on the lib/pq directory still takes about 38 seconds in Windows, compared to 0.132 secs or so in Linux / OSX.

If the expensive user.Current() call is cached (the system user name is unlikely to change), then in the scenario where the user option is not set (such as in go test for this package), the expensive call is only done once:

conn.go, line 23...

var (
ErrSSLNotSupported = errors.New("pq: SSL is not enabled on the server")
ErrNotSupported = errors.New("pq: invalid command")
systemUsername = ""
)

conn.go, line 69...

if o.Get("user") == "" {
    if systemUsername == "" {
        u, err := user.Current()
        if err != nil {
            return nil, err
        } else {
            systemUsername = u.Username
        }
    }
    o.Set("user", systemUsername)
}

go test now only takes about 2.3 seconds, and anyone affected will likely stop complaining.

[kisielk]

You need to have some form of synchronization around systemUsername otherwise you have a data race. I think it could be made even simpler though, just initialize systemUsername inside of the package's init() function so it happens just once at startup and then you don't need to perform any checks inside of Open.

[fdr]

Apparently this package which was located at bmizerany/pq as been moved over to this location, lib/pq.

Some effort has been paid to break builds using bmizerany/pq with an error message when one attempts to compile. Did it not work?

If the expensive user.Current() call is cached (the system user name is unlikely to change)

Unlikely, but but not impossible. Considering the availability of a workaround (set the user) I am not particularly positively disposed.

My vote for what it's worth is to remove the user.Current() call entirely, removing the problem in Windows and ensuring the user of the library makes the safer and clearer user= statement in their open call.

I'm not inclined to deviate from libpq behavior in this way.

I think there's a solution for all involved: to stop using user.current(). It looks like a lot of stuff is being done in there, but the GetUserName syscall is all that is necessary to get parity with libpq (apparently the Go standard library defines the username as domainAndUser and a bunch of more stuff is done to achieve that). So I think we can drop directly into using the syscall for Windows and the problems will be no different than libpq from then on.

We'd need to introduce build tags (which should be done anyhow, people keep sending Go 1.1 contributions, even before it was released...and I'm not about to break Go 1.0 people anyway). So, I'd gladly accept that.

Also, use of such syscalls would probably bust up including this in sandboxed environments where presumably access to the syscall package would not be allowed. I'm not sure if that's much of a thing, but it's worth thinking about for a few seconds.

But beyond that we'd need figure out some way to test it. Or, mercilessly break Windows whenever, which is the path of least resistance and a likely outcome unless someone figures out what to do in that department, and given my computers on hand it's almost certainly not going to be me.

The exact spot of the delay can be found (at least in the Go 1.1 source tree) at src/pkg/os/user/lookup_windows.go, line 18-19:

name, e := syscall.TranslateAccountName(domainAndUser,
    syscall.NameSamCompatible, syscall.NameDisplay, 50)

If you are not on a domain, this call seems to take about 2.3 seconds to time out. Commenting this line out has the pq go test run in about 0.6 seconds, compared to about 39 seconds with it in. An incredibly useful feature of how the whole go system is set up is that one can go into the released distribution, modify a library and re-compile anything without any other tools, installs, or whatnot. Amazingly the tests that are run from all.bat caught the fact that the user name was changed and a few things failed.

Compatibility with libpq as a reason for having this lookup mechanism in there in the first place seems like a pretty sound reason for it to be the way it is. Issues with synchronizing a possible cached value or accounting for the edge case where the value may change also appears to be good reasons for keeping the lookup in the Open() right where it is. The Windows domain name lookup is also doing what it should do; though perhaps there may be a way for the go os/user library to do that without incurring the timeout. So breaking this out and making a Windows specific version may not be all that useful as it would need to do much the same thing anyway, and would break one of the nice features about the pq library, that being that it is pure Go with no platform dependencies.

I think the code should remain exactly as it is; everything is there for a good reason and works as intended. Perhaps if something to the effect (less wordy?) of the following were added to "README.md" under the first "Connection String Parameters" section is all that is needed:

"If the user parameter is not set, the environment variable PGUSER is consulted. If that environment variable is not set, the go library function user.Current() from the Go system library os/user. Every call to Open() does these series of checks to determine the user name in which to open the postgreSQL database. On windows system, the call to user.Current() looks for a domain controller first before considering a local user name. If the windows system in question is not on a domain, this check takes about 2.3 seconds to time out and is blocking, thus adding the blocking timeout delay to the sql Open() call. If you wish to avoid incurring a delay from the domain-name check on Windows systems that are running without a domain controller, then either supply the "user" parameter or set the environment variable "PGUSER" to a valid value before calling Open().

As far as maintaining a performant and stable windows version (which currently is done with no extra effort) should remain a priority, as one of the main drawing cards to the combination of Go, postgreSQL and this pq library are that it works so seamlessly on all platforms. The current project I'm working on wound up with this combination for just that cross-platform reason, and looking through related comments it would appear to be a common thread from those using this combination of tools.

As far as someone ensuring compatibility, as the pq library has been added to the project I'm working on, it will be regressed nightly for at least the next 6-12 months on OSX, Linux, and Windows 7/8 platforms. I'd far rather contribute bug fixes back and use this lib/pq github version than forking it.

With respect to the old bmizerany/pq repository, it seemed to work just fine; but perhaps my remote update script wasn't pulling in the newest version for some reason. Augmenting or replacing the README.md file with a pointer to this new repository would be highly useful though.

[fdr]

As far as someone ensuring compatibility, as the pq library has been added to the project I'm working on, it will be regressed nightly for at least the next 6-12 months on OSX, Linux, and Windows 7/8 platforms. I'd far rather contribute bug fixes back and use this lib/pq github version than forking it.

That's good to hear. The main reason why I was suggesting regressions would take place if we introduced build tags for Windows is because I personally don't have any intention of setting up a Windows build farm thing (but would happily use one if someone did and I could see it before stuffing new code in master). If I had one, then Windows is much less likely to regress.

As-is I'm a bit concerned that pq's Windows username expansion is done differently than libpq: afaik, it doesn't expand the domain and does different (and notably, fewer) syscalls to do the deed. So that, too, is a probably-bug.

The concept of a username under Windows appears to have a long and storied history, with a variety of patches added on to throughout the years to support networking, domains, shared machines, and whatnot. As such, there doesn't seem to be a single right answer to the question of "what is my username" ... it depends. The windows code in the Go library os/user seems to be incomplete, but on the right track for supplying a "correct" answer to the Windows User name question.

lib/pq goal's though are not necessarily for the "correct" user name, but to work the same way that postgresql libpq does.

If you look through the source code of the current stable postgresql code, the part that looks up the user name on windows can be found at postgresql-9.2.4/src/bin/initdb/initdb.c, lines 609 to 623 as follows:

#else                           /* the windows code */

    struct passwd_win32
    {
        int         pw_uid;
        char        pw_name[128];
    }           pass_win32;
    struct passwd_win32 *pw = &pass_win32;
    DWORD       pwname_size = sizeof(pass_win32.pw_name) - 1;

    pw->pw_uid = 1;
    if (!GetUserName(pw->pw_name, &pwname_size))
    {
        fprintf(stderr, _("%s: could not get current user name: %s\n"),
                progname, strerror(errno));
        exit(1);
    }
#endif

The legacy Win32 function "GetUserName" is being used. Go does not export that function, but rather exports GetUserNameEx instead. To make the output of the Ex function the same as the older one, the base path needs to be returned - so that the value 'MYMACHINENAME/Fred' becomes simply 'Fred'. Using the GetUserNameEx directly instead of user.current() has two benifits: (1) lib/pq performs identically to libpq (or psql) under Windows; (2) it's very fast, eliminating the slowdown reported on this thread.

The patch / code is as follows:

In conn.go, remove os/user from imports, and change lines 67-72 as follows:

    if o.Get("user") == "" {
        u, err := userCurrent()
        if err != nil {
            return nil, err
        } else {
            o.Set("user", u)
        }
    }

Add a file "user_posix.go" with the following contents:

// Package pq is a pure Go Postgres driver for the database/sql package.

// +build darwin freebsd linux netbsd openbsd

package pq

import (
    "os/user"
)

func userCurrent() (string, error) {
    u, err := user.Current()
    if err != nil {
        return "", err
    } else {
        return u.Username, nil
    }
}

Add a file "user_windows.go" with contents as follows:

// Package pq is a pure Go Postgres driver for the database/sql package.
package pq

import (
    "path/filepath"
    "syscall"
)

// Perform Windows user name lookup identical to postgreSQL 9.2, who's user
// lookup functions can be found in postgresql-9.2.4/src/bin/initdb/initdb.c,
// lines 609 to 623.
//
// Note that the postgresql code makes use of the legacy win32 function
// GetUserName, and that function has not been imported into stock Go.
// GetUserNameEx is available though, the difference being that a wider range
// of names are available.  To get the output to be the same as GetUserName,
// only the base (or last) component of the result is returned.
func userCurrent() (string, error) {
    pw_name := make([]uint16, 128)
    pwname_size := uint32(len(pw_name)) - 1
    err := syscall.GetUserNameEx(syscall.NameSamCompatible, &pw_name[0], &pwname_size)
    if err != nil {
        return "", err
    } else {
        s := syscall.UTF16ToString(pw_name)
        u := filepath.Base(s)
        return u, nil
    }
}

Tested on Win7, Win8, Linux (Ubuntu), OSX.

As far as on-going maintenance is concerned, this windows dependency is a minor fringe case, unlikely to cause regression problems in the future. Ideally lib/pq would be regressed against windows machines in any case; but if it was not for whatever reason this change is unlikely to cause issues due to its limited scope.

[fdr]

Do you want to submit this as a pull request? Otherwise, LGTM; I can apply it by hand if you can't cook up the patch for some reason.

The pull request has been submitted, from the fork github.com/cwds/pq which contains the altered code. The fork was tested on WIn7, Win8, OSX, and Linux (Ubuntu) with PostgreSQL 9.2.4 and Go 1.1, plus Go Hg Head.

[brianoh]

@cwds. Thanks for your work in hopefully resolving this issue.

[brianoh]

I'm not in the position to test at present (travelling). Please confirm resolved and I'll close it.

[fdr]

I'll let someone who can reproduce this do the honors. @cwds, or anyone
else for that matter?