{"action":"created","issue":{"url":"https://api.github.com/repos/coreos/etcd/issues/4111","labels_url":"https://api.github.com/repos/coreos/etcd/issues/4111/labels{/name}","comments_url":"https://api.github.com/repos/coreos/etcd/issues/4111/comments","events_url":"https://api.github.com/repos/coreos/etcd/issues/4111/events","html_url":"https://github.com/coreos/etcd/issues/4111","id":124533815,"number":4111,"title":"Bad latency (100ms <) of storage","user":{"login":"mitake","id":1173955,"avatar_url":"https://avatars.githubusercontent.com/u/1173955?v=3","gravatar_id":"","url":"https://api.github.com/users/mitake","html_url":"https://github.com/mitake","followers_url":"https://api.github.com/users/mitake/followers","following_url":"https://api.github.com/users/mitake/following{/other_user}","gists_url":"https://api.github.com/users/mitake/gists{/gist_id}","starred_url":"https://api.github.com/users/mitake/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mitake/subscriptions","organizations_url":"https://api.github.com/users/mitake/orgs","repos_url":"https://api.github.com/users/mitake/repos","events_url":"https://api.github.com/users/mitake/events{/privacy}","received_events_url":"https://api.github.com/users/mitake/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/coreos/etcd/labels/area/performance","name":"area/performance","color":"bfe5bf"},{"url":"https://api.github.com/repos/coreos/etcd/labels/component/storage","name":"component/storage","color":"0052cc"}],"state":"open","locked":false,"assignee":{"login":"gyuho","id":6799218,"avatar_url":"https://avatars.githubusercontent.com/u/6799218?v=3","gravatar_id":"","url":"https://api.github.com/users/gyuho","html_url":"https://github.com/gyuho","followers_url":"https://api.github.com/users/gyuho/followers","following_url":"https://api.github.com/users/gyuho/following{/other_user}","gists_url":"https://api.github.com/users/gyuho/gists{/gist_id}","starred_url":"https://api.github.com/users/gyuho/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gyuho/subscriptions","organizations_url":"https://api.github.com/users/gyuho/orgs","repos_url":"https://api.github.com/users/gyuho/repos","events_url":"https://api.github.com/users/gyuho/events{/privacy}","received_events_url":"https://api.github.com/users/gyuho/received_events","type":"User","site_admin":false},"milestone":null,"comments":14,"created_at":"2016-01-01T06:41:43Z","updated_at":"2016-01-08T05:34:37Z","closed_at":null,"body":"https://github.com/coreos/etcd/pull/4070 added a new benchmark for stressing etcd storage. It found a very high latency of put process.\r\n\r\nWhen a number of written keys is not so large (e.g. 1000), the result will be like this:\r\n```\r\ntotal: 2.686489ms\r\naverage: 2.686µs\r\nminimum latency: 1.545µs\r\nmaximum latency: 18.209µs\r\n```\r\n\r\nWhen the number of keys is larger (e.g. 10000), the result will be like this:\r\n```\r\ntotal: 184.821125ms\r\naverage: 18.482µs\r\nrate: 54106.3691\r\nminimum latency: 1.719µs\r\nmaximum latency: 142.160798ms\r\n```\r\n\r\nThe high latency is also confirmed by @xiang90 : https://github.com/coreos/etcd/pull/4070#issuecomment-168287088\r\n\r\nThe result can be easily reproduced with the benchmark e.g. `./benchmark storage put --total 10000`."},"comment":{"url":"https://api.github.com/repos/coreos/etcd/issues/comments/169900852","html_url":"https://github.com/coreos/etcd/issues/4111#issuecomment-169900852","issue_url":"https://api.github.com/repos/coreos/etcd/issues/4111","id":169900852,"user":{"login":"gyuho","id":6799218,"avatar_url":"https://avatars.githubusercontent.com/u/6799218?v=3","gravatar_id":"","url":"https://api.github.com/users/gyuho","html_url":"https://github.com/gyuho","followers_url":"https://api.github.com/users/gyuho/followers","following_url":"https://api.github.com/users/gyuho/following{/other_user}","gists_url":"https://api.github.com/users/gyuho/gists{/gist_id}","starred_url":"https://api.github.com/users/gyuho/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/gyuho/subscriptions","organizations_url":"https://api.github.com/users/gyuho/orgs","repos_url":"https://api.github.com/users/gyuho/repos","events_url":"https://api.github.com/users/gyuho/events{/privacy}","received_events_url":"https://api.github.com/users/gyuho/received_events","type":"User","site_admin":false},"created_at":"2016-01-08T05:34:37Z","updated_at":"2016-01-08T05:34:37Z","body":"Basically benchmark script does:\r\n\r\n```go\r\nbe := backend.New(\"storage-bench\", time.Duration(batchInterval), batchLimit)\r\ns = storage.NewStore(be)\r\n\r\nfor {\r\n    s.Put(keys[i], vals[i], lease.NoLease)\r\n}\r\n```\r\n\r\nAnd these are two concurrent routines:\r\n\r\n1. `backend.New` launches a goroutine [`go b.run()`](https://github.com/coreos/etcd/blob/master/storage/backend/backend.go#L147-L159) that does `b.batchTx.Commit()` periodically with `defaultBatchInterval`, which is 100ms. `b.batchTx.Commit()` does its own `b.batchTx.Lock()` and `b.batchTx.Unlock()`.\r\n2. [`store.Put`](https://github.com/coreos/etcd/blob/master/storage/kvstore.go#L100) calls the following sequentially:\r\n  1. `store.TxnBegin`: begins the transaction by grabbing `store.backend.batchTx.Lock()`. And this blocks if there were contention.\r\n  2. `store.put`: actually write to database with:\r\n     - `store.backend.batchTx.UnsafePut(keyBucketName, ibytes, d)`\r\n     - `store.kvindex.Put(key, revision{main: rev, sub: s.currentRev.sub})`\r\n  3. `store.txnEnd`: just `store.backend.batchTx.Unlock()` and `store.mu.Unlock()`. Doesn't increase latency.\r\n\r\nSo there could be contention between `b.batchTx.Commit()` and `store.backend.batchTx.Lock()`.\r\n- `backend.New` does `b.batchTx.Lock` to periodically commit to disk in the background. \r\n- `store.Put` does `store.backend.batchTx.Lock()` to read and write from `store.kvindex` and safely write to `store.batchTx`.\r\n\r\n<br>\r\n\r\nWith: \r\n\r\n```go\r\nvar cnt int\r\n\r\nfunc (t *batchTx) commit(stop bool) {\r\n\tvar err error\r\n\t// commit the last tx\r\n\tif t.tx != nil {\r\n\t\tif t.pending == 0 && !stop {\r\n\t\t\treturn\r\n\t\t}\r\n\r\n\t\terr = t.tx.Commit()\r\n\t\tif err != nil {\r\n\t\t\tlog.Fatalf(\"storage: cannot commit tx (%s)\", err)\r\n\t\t}\r\n\t\tstat := t.tx.Stats()\r\n\t\ttook := stat.WriteTime\r\n\t\tif took > 100*time.Millisecond {\r\n\t\t\tfmt.Println()\r\n\t\t\tfmt.Printf(\"t.pending: %d at %d th commit\\n\", t.pending, cnt)\r\n\t\t\tfmt.Printf(\"t.tx.Stats(): %+v\\n\", stat)\r\n\t\t\tfmt.Printf(\"backend.db.Stats(): %+v\\n\", t.backend.db.Stats())\r\n\t\t\tfmt.Println()\r\n\t\t}\r\n\t\tt.pending = 0\r\n\t}\r\n\tcnt++\r\n\r\n\tif stop {\r\n\t\treturn\r\n\t}\r\n\r\n\t// begin a new tx\r\n\tt.tx, err = t.backend.db.Begin(true)\r\n\tif err != nil {\r\n\t\tlog.Fatalf(\"storage: cannot begin tx (%s)\", err)\r\n\t}\r\n\tatomic.StoreInt64(&t.backend.size, t.tx.Size())\r\n}\r\n\r\n```\r\n\r\nThis prints out:\r\n\r\n> t.pending: 269 at 37 th commit\r\n> t.tx.Stats(): {PageCount:30 PageAlloc:122880 CursorCount:271 NodeCount:4 NodeDeref:0 Rebalance:0 RebalanceTime:0 Split:25 Spill:29 SpillTime:111.067µs Write:31 WriteTime:139.696706ms}\r\nbackend.db.Stats(): {FreePageN:0 PendingPageN:5 FreeAlloc:20480 FreelistInuse:56 TxN:0 OpenTxN:0 TxStats:{PageCount:657 PageAlloc:2691072 CursorCount:5344 NodeCount:135 NodeDeref:201 Rebalance:0 RebalanceTime:0 Split:483 Spill:620 SpillTime:219.51264ms Write:694 WriteTime:1.961095921s}}\r\n\r\n>t.pending: 219 at 69 th commit\r\nt.tx.Stats(): {PageCount:25 PageAlloc:102400 CursorCount:221 NodeCount:4 NodeDeref:0 Rebalance:0 RebalanceTime:0 Split:20 Spill:24 SpillTime:109.701µs Write:26 WriteTime:139.98227ms}\r\nbackend.db.Stats(): {FreePageN:0 PendingPageN:5 FreeAlloc:20480 FreelistInuse:56 TxN:0 OpenTxN:0 TxStats:{PageCount:1237 PageAlloc:5066752 CursorCount:9956 NodeCount:263 NodeDeref:253 Rebalance:0 RebalanceTime:0 Split:903 Spill:1168 SpillTime:266.892494ms Write:1306 WriteTime:3.550703711s}}\r\n\r\n\r\n```\r\ntotal: 3.913850451s\r\naverage: 391.385µs\r\nrate: 2555.0286\r\nminimum latency: 1.523µs\r\nmaximum latency: 141.894603ms\r\n\r\n```\r\n\r\n\r\n`Write` in Txn stats is the number of writes performed. And it varies so it's hard to tell what number of writes increase the latency in transaction.\r\n\r\nAnd if you record the number of keys at the time of transaction:\r\n\r\n> t.pending: 91 at 26 th commit\r\nt.num: 4621\r\nt.tx.Stats(): {PageCount:13 PageAlloc:53248 CursorCount:93 NodeCount:4 NodeDeref:0 Rebalance:0 RebalanceTime:0 Split:8 Spill:12 SpillTime:65.784µs Write:14 WriteTime:140.489183ms}\r\nbackend.db.Stats(): {FreePageN:0 PendingPageN:5 FreeAlloc:20480 FreelistInuse:56 TxN:0 OpenTxN:0 TxStats:{PageCount:545 PageAlloc:2232320 CursorCount:4679 NodeCount:94 NodeDeref:383 Rebalance:0 RebalanceTime:0 Split:423 Spill:519 SpillTime:234.64762ms Write:571 WriteTime:1.45660335s}}\r\n\r\n> t.pending: 604 at 42 th commit\r\nt.num: 8562\r\nt.tx.Stats(): {PageCount:61 PageAlloc:249856 CursorCount:606 NodeCount:4 NodeDeref:0 Rebalance:0 RebalanceTime:0 Split:56 Spill:60 SpillTime:143.961µs Write:62 WriteTime:425.110508ms}\r\nbackend.db.Stats(): {FreePageN:0 PendingPageN:5 FreeAlloc:20480 FreelistInuse:56 TxN:0 OpenTxN:0 TxStats:{PageCount:990 PageAlloc:4055040 CursorCount:8652 NodeCount:158 NodeDeref:387 Rebalance:0 RebalanceTime:0 Split:788 Spill:948 SpillTime:274.612466ms Write:1032 WriteTime:2.59967088s}}\r\n\r\nEvery 3000 or 4000 key, the latency spikes, but this also varies."}}