Low CPU usage indicate IO bottleneck: default benchmark should consume approximately 1.5GB of memory on 64-bit OS platform (800MB for preparing benchmark data, 700MB for actual database buffer)

How much memory were available to benchmark at time of the execution?

from tiedot.

See also my notes about file buffer VS available memory:

https://github.com/HouzuoGuo/tiedot/wiki/Performance-and-benchmarks#when-data-size--available-memory-1

from tiedot.

I did't mount /tmp to mem disk, is that the reason?

$ free
             total       used       free     shared    buffers     cached
Mem:       3616092     685660    2930432          0      73144     318600
-/+ buffers/cache:     293916    3322176
Swap:      1046524          0    1046524

from tiedot.

That shouldn't be required.

Please check number of processors allocated to VirtualBox guest, as well as processor cap.

from tiedot.

I set 4 cores with full cap.

Does tiedot support windows? I'll test it on my host OS again.

from tiedot.

seems not well supported yet. It still creating file in /tmp/tiedot_bench/ path, where would it be ?

E:\ifqdata\godir\bin>tiedot.exe -mode=bench
2013/08/14 14:09:41 GOMAXPROCS is set to 8
2013/08/14 14:09:49 File /tmp/tiedot_bench/data has grown 134217728 bytes
2013/08/14 14:09:50 File /tmp/tiedot_bench/a,b,c330279820 has grown 67108864 byt
es
2013/08/14 14:09:51 File /tmp/tiedot_bench/a,b,c330279820 has grown 67108864 byt
es
2013/08/14 14:09:53 File /tmp/tiedot_bench/c,d-1838417476 has grown 67108864 byt
es
2013/08/14 14:09:54 File /tmp/tiedot_bench/c,d-1838417476 has grown 67108864 byt
es
insert 400000: 6768 ns/iter, 147746 iter/sec
runtime: memory allocated by OS (0xbb0000) not in usable range [0x11fa0000,0x91f
a0000)
runtime: out of memory: cannot allocate 65536-byte block (1105461248 in use)
fatal error: out of memory

goroutine 1 [running]:
[fp=0x6ce7bd20] runtime.throw(0xa05c30)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/panic.c:473 +0x65
[fp=0x6ce7bd40] runtime.MCache_Alloc(0xb709d0, 0xa, 0x90, 0x0)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/mcache.c:27 +0x96
[fp=0x6ce7bd70] runtime.mallocgc(0x90, 0x0, 0x1, 0x0)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/zmalloc_windows_386.c:47 +0xdf
[fp=0x6ce7bdbc] hash_insert(0x55d760, 0x7feecca0, 0x6ce7bdf4, 0x6ce7bdfc)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/hashmap.c:599 +0x7e
[fp=0x6ce7bdd0] runtime.mapassign(0x55d760, 0x7feecca0, 0x6ce7bdf4, 0x6ce7bdfc)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/hashmap.c:1272 +0x89
[fp=0x6ce7bdec] runtime.mapassign1()
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/hashmap.c:1301 +0x5c
[fp=0x6ce7be28] encoding/json.(*decodeState).objectInterface(0x7feefd80, 0x9)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:822 +0x1b7
[fp=0x6ce7be44] encoding/json.(*decodeState).valueInterface(0x7feefd80, 0x3, 0x5
ec80b5)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:756 +0x66
[fp=0x6ce7be80] encoding/json.(*decodeState).objectInterface(0x7feefd80, 0x7fee9
dc8)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:822 +0x183
[fp=0x6ce7bfcc] encoding/json.(*decodeState).object(0x7feefd80, 0x561fe0, 0x7fee
9dc8, 0x146)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:450 +0x12f
----- stack segment boundary -----
[fp=0x1201492c] encoding/json.(*decodeState).value(0x7feefd80, 0x557460, 0x7fee9
dc8, 0x160)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:285 +0x1e7
[fp=0x1201497c] encoding/json.(*decodeState).unmarshal(0x7feefd80, 0x557460, 0x7
fee9dc8, 0x0, 0x0, ...)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:145 +0x11e
[fp=0x1201499c] encoding/json.Unmarshal(0x34d87f33, 0x9a, 0x5ec80cd, 0x557460, 0
x7fee9dc8, ...)
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:74 +0xb0
[fp=0x120149e8] loveoneanother.at/tiedot/db.func路009(0x2137f28, 0x0, 0x34d87f33
, 0x9a, 0x5ec80cd, ...)
        E:/ifqdata/godir/src/loveoneanother.at/tiedot/db/col.go:375 +0x67
[fp=0x12014a88] loveoneanother.at/tiedot/file.(*ColFile).ForAll(0x11fec040, 0x12
014a90)
        E:/ifqdata/godir/src/loveoneanother.at/tiedot/file/col.go:122 +0x421
[fp=0x12014aa0] loveoneanother.at/tiedot/db.(*Col).ForAll(0x11fee210, 0x12014aa8
)
        E:/ifqdata/godir/src/loveoneanother.at/tiedot/db/col.go:381 +0x51
[fp=0x12014ab4] main.func路005()
        E:/ifqdata/godir/src/loveoneanother.at/tiedot/benchmark.go:73 +0x42
[fp=0x12014bd8] main.average(0x5c2528, 0x4, 0x61a80, 0x123220ac, 0x54586a50, ...
)
        E:/ifqdata/godir/src/loveoneanother.at/tiedot/benchmark.go:21 +0xc2
[fp=0x123220bc] main.benchmark()
        E:/ifqdata/godir/src/loveoneanother.at/tiedot/benchmark.go:80 +0x55e
----- stack segment boundary -----
[fp=0xbc17c4] main.main()
        E:/ifqdata/godir/src/loveoneanother.at/tiedot/main.go:53 +0x31d
[fp=0xbc17dc] runtime.main()
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/proc.c:182 +0x8e
[fp=0xbc17e0] runtime.goexit()
        C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/proc.c:1223

from tiedot.

I think windows treats leading slash as current working directory. I tested tiedot on windows 7 64-bit (my laptop) , with 4gb memory on board, all benchmark and test cases ran successfully. The error ‎appears to be memory exhaustion. Which version of windows are you running?  From: ifqSent: Wednesday, 14 August 2013 16:13To: HouzuoGuo/tiedotReply To: HouzuoGuo/tiedotCc: Howard GuoSubject: Re: [tiedot] is this performance ok on my virtualbox? (#19)seems not well supported yet. It still creating file in /tmp/tiedot_bench/ path, where would it be ?

E:\ifqdata\godir\bin>tiedot.exe -mode=bench
2013/08/14 14:09:41 GOMAXPROCS is set to 8
2013/08/14 14:09:49 File /tmp/tiedot_bench/data has grown 134217728 bytes
2013/08/14 14:09:50 File /tmp/tiedot_bench/a,b,c330279820 has grown 67108864 byt
es
2013/08/14 14:09:51 File /tmp/tiedot_bench/a,b,c330279820 has grown 67108864 byt
es
2013/08/14 14:09:53 File /tmp/tiedot_bench/c,d-1838417476 has grown 67108864 byt
es
2013/08/14 14:09:54 File /tmp/tiedot_bench/c,d-1838417476 has grown 67108864 byt
es
insert 400000: 6768 ns/iter, 147746 iter/sec
runtime: memory allocated by OS (0xbb0000) not in usable range [0x11fa0000,0x91f
a0000)
runtime: out of memory: cannot allocate 65536-byte block (1105461248 in use)
fatal error: out of memory

goroutine 1 [running]:
[fp=0x6ce7bd20] runtime.throw(0xa05c30)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/panic.c:473 +0x65
[fp=0x6ce7bd40] runtime.MCache_Alloc(0xb709d0, 0xa, 0x90, 0x0)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/mcache.c:27 +0x96
[fp=0x6ce7bd70] runtime.mallocgc(0x90, 0x0, 0x1, 0x0)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/zmalloc_windows_386.c:47 +0xdf
[fp=0x6ce7bdbc] hash_insert(0x55d760, 0x7feecca0, 0x6ce7bdf4, 0x6ce7bdfc)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/hashmap.c:599 +0x7e
[fp=0x6ce7bdd0] runtime.mapassign(0x55d760, 0x7feecca0, 0x6ce7bdf4, 0x6ce7bdfc)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/hashmap.c:1272 +0x89
[fp=0x6ce7bdec] runtime.mapassign1()
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/hashmap.c:1301 +0x5c
[fp=0x6ce7be28] encoding/json.(_decodeState).objectInterface(0x7feefd80, 0x9)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:822 +0x1b7
[fp=0x6ce7be44] encoding/json.(_decodeState).valueInterface(0x7feefd80, 0x3, 0x5
ec80b5)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:756 +0x66
[fp=0x6ce7be80] encoding/json.(_decodeState).objectInterface(0x7feefd80, 0x7fee9
dc8)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:822 +0x183
[fp=0x6ce7bfcc] encoding/json.(_decodeState).object(0x7feefd80, 0x561fe0, 0x7fee
9dc8, 0x146)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:450 +0x12f
----- stack segment boundary -----
[fp=0x1201492c] encoding/json.(_decodeState).value(0x7feefd80, 0x557460, 0x7fee9
dc8, 0x160)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:285 +0x1e7
[fp=0x1201497c] encoding/json.(_decodeState).unmarshal(0x7feefd80, 0x557460, 0x7
fee9dc8, 0x0, 0x0, ...)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:145 +0x11e
[fp=0x1201499c] encoding/json.Unmarshal(0x34d87f33, 0x9a, 0x5ec80cd, 0x557460, 0
x7fee9dc8, ...)
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/encod
ing/json/decode.go:74 +0xb0
[fp=0x120149e8] loveoneanother.at/tiedot/db.func路009(0x2137f28, 0x0, 0x34d87f33
, 0x9a, 0x5ec80cd, ...)
E:/ifqdata/godir/src/loveoneanother.at/tiedot/db/col.go:375 +0x67
[fp=0x12014a88] loveoneanother.at/tiedot/file.(_ColFile).ForAll(0x11fec040, 0x12
014a90)
E:/ifqdata/godir/src/loveoneanother.at/tiedot/file/col.go:122 +0x421
[fp=0x12014aa0] loveoneanother.at/tiedot/db.(_Col).ForAll(0x11fee210, 0x12014aa8
)
E:/ifqdata/godir/src/loveoneanother.at/tiedot/db/col.go:381 +0x51
[fp=0x12014ab4] main.func路005()
E:/ifqdata/godir/src/loveoneanother.at/tiedot/benchmark.go:73 +0x42
[fp=0x12014bd8] main.average(0x5c2528, 0x4, 0x61a80, 0x123220ac, 0x54586a50, ...
)
E:/ifqdata/godir/src/loveoneanother.at/tiedot/benchmark.go:21 +0xc2
[fp=0x123220bc] main.benchmark()
E:/ifqdata/godir/src/loveoneanother.at/tiedot/benchmark.go:80 +0x55e
----- stack segment boundary -----
[fp=0xbc17c4] main.main()
E:/ifqdata/godir/src/loveoneanother.at/tiedot/main.go:53 +0x31d
[fp=0xbc17dc] runtime.main()
C:/Users/ADMINI1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/proc.c:182 +0x8e
[fp=0xbc17e0] runtime.goexit()
C:/Users/ADMINI~1/AppData/Local/Temp/2/bindist934530519/go/src/pkg/runti
me/proc.c:1223

—Reply to this email directly or view it on GitHub.

from tiedot.

My host OS is win7 32bit, with patch to break 4G memory restriction.. although I'm runing virtualbox, it should still have 2G+ memory.

from tiedot.

Ok, are you aware of this 3 years old Go bug‎.... your laptop is a victim ‎http://code.google.com/p/go/issues/detail?id=909 From: ifqSent: Wednesday, 14 August 2013 16:57To: HouzuoGuo/tiedotReply To: HouzuoGuo/tiedotCc: Howard GuoSubject: Re: [tiedot] is this performance ok on my virtualbox? (#19)My host OS is win7 32bit, with patch to break 4G memory restriction.. although I'm runing virtualbox, it should still have 2G+ memory.

—Reply to this email directly or view it on GitHub.

from tiedot.

It's a annoying problem :( My app's target user is win32 user... did't realize go has this kind of issue...
I actully met this problem with a test program, whichi I try to alloc a large map, but I ignored it..

But I don't think my app needs that much memory. It only happens when large amount memory used, like 1G+ ,right?

from tiedot.

Indeed, especially for a DB type program, in which lot of objects are disposable, used once and never again.

from tiedot.

tiedot incurs lot of GC activities not due to buffer management, but due to data serialization and deserialization - document comes in, it is serialized (for indexing) then deserialized for storage, therefore lot of objects are disposable - used once and never again.

Go's GC is inefficient on 32-bit platforms. If your data file is small (i.e. small data buffer), GC may run just fine; but if you have large data files (multi GB of data buffer), GC in the situation may not have enough free memory to action effectively.

We can wait for Go to address this issue, or alternatively please use 64-bit OS.

from tiedot.

crash on 32bit os is another issue, but this issue is about low performance on virtualbox.

from tiedot.

All right.

In benchmark.go, change BENCH_SIZE from 400,000 to 200,000 and re-run benchmark, please report back performance result.

Then please set it to 100,000 and report back benchmark result.

from tiedot.

bench_size = 200,000

$ tiedot -mode=bench
2013/08/16 17:42:02 GOMAXPROCS is set to 8
2013/08/16 17:42:11 File /tmp/tiedot_bench/data has grown 134217728 bytes
2013/08/16 17:42:14 File /tmp/tiedot_bench/a,b,c-806663946 has grown 67108864 bytes
2013/08/16 17:42:17 File /tmp/tiedot_bench/a,b,c-806663946 has grown 67108864 bytes
2013/08/16 17:42:20 File /tmp/tiedot_bench/c,d1524934145 has grown 67108864 bytes
2013/08/16 17:42:22 File /tmp/tiedot_bench/c,d1524934145 has grown 67108864 bytes
insert 200000: 611359 ns/iter, 1635 iter/sec
read 200000: 10970 ns/iter, 91154 iter/sec
lookup 200000: 24794 ns/iter, 40331 iter/sec
update 200000: 2306164 ns/iter, 433 iter/sec
delete 200000: 964425 ns/iter, 1036 iter/sec

bench_size = 100,000

2013/08/16 18:15:01 GOMAXPROCS is set to 8
2013/08/16 18:15:08 File /tmp/tiedot_bench/data has grown 134217728 bytes
2013/08/16 18:15:12 File /tmp/tiedot_bench/a,b,c1230876522 has grown 67108864 bytes
2013/08/16 18:15:14 File /tmp/tiedot_bench/a,b,c1230876522 has grown 67108864 bytes
2013/08/16 18:15:16 File /tmp/tiedot_bench/c,d-2083726430 has grown 67108864 bytes
2013/08/16 18:15:19 File /tmp/tiedot_bench/c,d-2083726430 has grown 67108864 bytes
insert 100000: 236942 ns/iter, 4220 iter/sec
read 100000: 8351 ns/iter, 119735 iter/sec
lookup 100000: 25498 ns/iter, 39218 iter/sec
update 100000: 1538393 ns/iter, 650 iter/sec
delete 100000: 501429 ns/iter, 1994 iter/sec

from tiedot.

Thank you.

It doesn't look like memory exhaustion. Unfortunately I do not own a 32-bit OS platform here therefore I do not have a definitive answer.

Since the benchmark does not maximize CPU usage, given that Go has an infamous GC bug on 32-bit platform, my gut feeling is that GC holds up goroutines execution too often during the benchmark - Go has to halt all goroutines in order to GC, which is a huge performance impact and hits 32-bit platform the hardest.

I am afraid there isn't much we can do to help.

from tiedot.

checkout bench result on win32, before program crash,

2013/08/14 14:09:54 File /tmp/tiedot_bench/c,d-1838417476 has grown 67108864 byt
es
insert 400000: 6768 ns/iter, 147746 iter/sec

this performance seems ok. so , it may not related to 32bit os.

from tiedot.

In virtualbox, did you observe CPU usage pattern like in this screenshot during benchmark?

This pattern indicates lack of freeable memory during benchmark.

from tiedot.

during the test process, CPU run like this(not showing the whole test):

from tiedot.

If you don't mind, I would like to park it for now until I get a hands on experience with 32-bit OS.

from tiedot.

That's ok. not a big problem for me now~

from tiedot.

could you please try the latest tiedot in master branch and let me know if you still encounter the issue?

if the issue still happens, please post CPU history and memory usage history graphs.

from tiedot.

Please try the latest master or 1.0 branch, there should be some improvements.

from tiedot.

From Beta to 1.1, the following major improvements were made:

• Greatly reduced memory consumption
• More granular locking system

Which will help tiedot to run better in 32-bit environments, including your virtualbox environment.

from tiedot.