Severe performance problems on 1.5 with bcrypt.CompareHashAndPassword()

[Nigel Vickers]

While  moving to go 1.5 we register that bcrypt.CompareHashAndPassword() takes 4.5 seconds to execute when run in our application.

SessionDump &{0TCe5j-_qSu8FIeVBQmDN1 false {63584465813 411476130 0xe20f80} {63584465828 558786836 0xe20f80} map[RDS:0xc8203e1a40] map[Lang:de hiddenPan:0xc820425cc0 ips:xx.xx.xxx.xx] 300000000000 0xc820451d00}
Rxxxx Dev2015/11/30 08:37:08 serveHTTP appName Parts   3 [ RDS e]
Rxxxx Dev2015/11/30 08:37:08    Event from comp: 36  event: 0
rbac.CheckDBC db returned hash $2a$12$POqiCemuLIFfpwSukrZR4un61NfSxxxxxxxxxxxxxxxxxxxxxxxxx
SCHED 32221ms: gomaxprocs=6 idleprocs=5 threads=9 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0 0 0]
SCHED 33228ms: gomaxprocs=6 idleprocs=5 threads=9 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0 0 0]
SCHED 34234ms: gomaxprocs=6 idleprocs=5 threads=9 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0 0 0]
SCHED 35241ms: gomaxprocs=6 idleprocs=5 threads=9 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0 0 0]
SCHED 36247ms: gomaxprocs=6 idleprocs=5 threads=9 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0 0 0]
rbac.CheckDBC sql.Open took 3.630088ms to run.
rbac.CheckDBC db.QueryRow(select dbhash) took  10.799249ms to run.
rbac.CheckDBC bcrypt.CompareHashAndPassword took 4.575247394s to run.
write session register result: {0xc820443260 1} <nil>

When the same function in the same environment is called from test it takes 360ms.

sysop@godev:~/go/src/t-rbac$ go test -v rbac_test.go
=== RUN   Test_VM
rbact genfrompassword took 364.745932ms to generate
rbact comparehashandpassword took 362.068234ms to compare
--- PASS: Test_VM (0.73s)
PASS
ok      command-line-arguments  0.736s

Observed with nmon we observe in test clean mapping of the load to all three available cores. However in the application the function appears to be locked to one core which appears to account for the extreme performance degradation. I am unable to register resource limitations. Pprof doesn’t indicate any locked syscalls.

Could someone suggest a way to Debug this?.

thanks,

Nigel Vickers

[mjy]

When your application runs, it uses bcrypt() with a cost parameter of 12, i.e. 2^12 key expansion rounds. The cost parameter is stored in the hash (the $12$ part), this is why the same code can behave in seemingly different ways. In your test you probably have a stored hash with a lower cost parameter (8?).

Details: https://en.wikipedia.org/wiki/Bcrypt

[Nigel Vickers]

Thanks, but the cost is the same, 12 is default in the wrapper function, bcrypt. default is 10, and the difference is about 12 % in runtime. 

[Nigel Vickers]

Somebody help an OAP across the road.

What does tsan_read mean in this context?

Showing top 10 nodes out of 26 (cum >= 1.27s)

      flat  flat%   sum%        cum   cum%

     3.05s 66.16% 66.16%      3.05s 66.16%  __tsan_read

     0.45s  9.76% 75.92%      1.24s 26.90%  golang.org/x/crypto/blowfish.encryptBlock

     0.43s  9.33% 85.25%      0.43s  9.33%  racecall

     0.40s  8.68% 93.93%      0.40s  8.68%  racecalladdr

     0.11s  2.39% 96.31%      0.11s  2.39%  runtime.raceread

     0.06s  1.30% 97.61%      0.06s  1.30%  __tsan_func_exit

     0.04s  0.87% 98.48%      0.04s  0.87%  __tsan_write

     0.03s  0.65% 99.13%      0.03s  0.65%  __tsan_func_enter

     0.03s  0.65% 99.78%      1.27s 27.55%  golang.org/x/crypto/blowfish.ExpandKey

[Will Newton]

On Mon, Nov 30, 2015 at 2:57 PM, Nigel Vickers <rhe...@gmail.com> wrote:
> Somebody help an OAP across the road.
> What does tsan_read mean in this context?

Thread sanitizer - race detection, which should be disabled before profiling.

> --
> 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.

[Nigel Vickers]

Thanks Will that was it. The race detector was compiled in and making a complete mess of bcrypt. Take it out and test and application run the same in the same time scale. OUCH! 

430ms of 430ms total (  100%)

Showing top 10 nodes out of 55 (cum >= 30ms)

      flat  flat%   sum%        cum   cum%

     360ms 83.72% 83.72%      360ms 83.72%  golang.org/x/crypto/blowfish.encryptBlock

      40ms  9.30% 93.02%       40ms  9.30%  crypto/elliptic.p256ReduceDegree

      10ms  2.33% 95.35%      370ms 86.05%  golang.org/x/crypto/bcrypt.expensiveBlowfishSetup

      10ms  2.33% 97.67%       10ms  2.33%  runtime.makeslice

      10ms  2.33%   100%       10ms  2.33%  syscall.Syscall

         0     0%   100%       10ms  2.33%  bufio.(*Writer).Flush

         0     0%   100%       10ms  2.33%  bufio.(*Writer).flush

         0     0%   100%       10ms  2.33%  crypto/elliptic.GenerateKey

         0     0%   100%       10ms  2.33%  crypto/elliptic.p256Curve.ScalarBaseMult

         0     0%   100%       30ms  6.98%  crypto/elliptic.p256Curve.ScalarMult