Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

sql: zero SQL mem pool on OpenBSD prevents clients from connecting #15836

Closed
mrijkeboer opened this issue May 10, 2017 · 10 comments
Closed

sql: zero SQL mem pool on OpenBSD prevents clients from connecting #15836

mrijkeboer opened this issue May 10, 2017 · 10 comments
Labels
C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. E-easy Easy issue to tackle, requires little or no CockroachDB experience O-community Originated from the community
Milestone
Later

Comments

@mrijkeboer
Copy link

BUG REPORT

When I try to connect to a cluster that is running on OpenBSD I get the following error:

$ cockroach sql --host=127.0.0.1 --insecure                                   
Error: unable to connect or connection lost.

Please check the address and credentials such as certificates (if attempting to
communicate with a secure cluster).

EOF
Failed running "sql"

The cluster is started with the following command:

$ cockroach start --insecure --host=127.0.0.1 --logtostderr --vmodule=mem_usage=2

Headers of most recent log file:

$ grep -F '[config]' cockroach-data/logs/cockroach.log
I170510 10:08:24.247772 1 util/log/clog.go:1011  [config] file created at: 2017/05/10 10:08:24
I170510 10:08:24.247772 1 util/log/clog.go:1011  [config] running on machine: crush
I170510 10:08:24.247772 1 util/log/clog.go:1011  [config] binary: CockroachDB CCL 0f59bf400 (openbsd amd64, built 2017/05/06 17:13:15, go1.8.1)
I170510 10:08:24.247772 1 util/log/clog.go:1011  [config] arguments: [cockroach start --insecure --host=127.0.0.1 --logtostderr --vmodule=mem_usage=2]

On the Cockroach forum @knz asked me to run the cluster with the --vmodule=mem_usage=2 option and provide the output:

I170510 10:08:24.247714 1 cli/start.go:575  CockroachDB CCL 0f59bf400 (openbsd amd64, built 2017/05/06 17:13:15, go1.8.1)
I170510 10:08:24.357099 12 cli/start.go:338  starting cockroach node
W170510 10:08:24.357166 12 server/server.go:162  running in insecure mode, this is strongly discouraged. See --insecure.
I170510 10:08:24.357727 12 server/server.go:268  root: starting monitor, reserved 0 B, pool (none)
I170510 10:08:24.357974 12 sql/distsqlrun/server.go:116  [n?] distsql: starting monitor, reserved 0 B, pool root
I170510 10:08:24.378286 12 sql/pgwire/server.go:168  sql: starting monitor, reserved 0 B, pool root
I170510 10:08:24.378314 12 sql/pgwire/server.go:174  conn: starting monitor, reserved 0 B, pool sql
I170510 10:08:24.397473 12 server/admin.go:87  admin: starting unlimited monitor
I170510 10:08:24.398145 12 storage/engine/rocksdb.go:379  opening rocksdb instance at "/home/user/Temp/db1/cockroach-data"
I170510 10:08:24.405754 12 server/config.go:421  1 storage engine initialized
I170510 10:08:24.406301 12 server/node.go:454  [n?] store [n0,s0] not bootstrapped
I170510 10:08:24.410146 12 server/node.go:389  [n?] **** cluster 1cf056a9-2ffc-402e-b68c-e873197b4168 has been created
I170510 10:08:24.410165 12 server/node.go:390  [n?] **** add additional nodes by specifying --join=127.0.0.1:26257
I170510 10:08:24.410803 12 storage/store.go:1250  [n1] [n1,s1]: failed initial metrics computation: [n1,s1]: system config not yet available
I170510 10:08:24.410835 12 server/node.go:467  [n1] initialized store [n1,s1]: {Capacity:116566335488 Available:99169796096 RangeCount:1 LeaseCount:0}
I170510 10:08:24.410857 12 server/node.go:351  [n1] node ID 1 initialized
I170510 10:08:24.410941 12 gossip/gossip.go:297  [n1] NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:26257" > attrs:<> locality:<> 
I170510 10:08:24.411242 12 storage/stores.go:296  [n1] read 0 node addresses from persistent storage
I170510 10:08:24.411318 12 server/node.go:608  [n1] connecting to gossip network to verify cluster ID...
I170510 10:08:24.412596 12 server/node.go:633  [n1] node connected via gossip and verified as part of cluster "1cf056a9-2ffc-402e-b68c-e873197b4168"
I170510 10:08:24.412625 12 server/node.go:405  [n1] node=1: started with [[]=/home/user/Temp/db1/cockroach-data] engine(s) and attributes []
I170510 10:08:24.412701 12 sql/executor.go:338  [n1] creating distSQLPlanner with address {tcp 127.0.0.1:26257}
I170510 10:08:24.412772 12 sql/session_mem_usage.go:126  [startup,n1] root: starting unlimited monitor
I170510 10:08:24.412788 12 sql/session_mem_usage.go:135  [startup,n1] session: starting monitor, reserved 0 B, pool root
I170510 10:08:24.416427 12 sql/session.go:378  [startup,n1] session, memory usage max 0 B
I170510 10:08:24.416444 12 sql/mon/mem_usage.go:588  [startup,n1] session: releasing 0 bytes to the pool
I170510 10:08:24.416459 12 sql/session.go:379  [startup,n1] root, memory usage max 0 B
I170510 10:08:24.416468 12 sql/mon/mem_usage.go:588  [startup,n1] root: releasing 0 bytes to the pool
I170510 10:08:24.416491 12 server/server.go:741  [n1] starting http server at 127.0.0.1:8080
I170510 10:08:24.416506 12 server/server.go:742  [n1] starting grpc/postgres server at 127.0.0.1:26257
I170510 10:08:24.416520 12 server/server.go:743  [n1] advertising CockroachDB node at 127.0.0.1:26257
I170510 10:08:24.417549 131 storage/split_queue.go:92  [split,n1,s1,r1/1:/M{in-ax}] splitting at key /System/""
I170510 10:08:24.421241 12 sql/session_mem_usage.go:126  [n1] root: starting unlimited monitor
I170510 10:08:24.421256 12 sql/session_mem_usage.go:135  [n1] session: starting monitor, reserved 0 B, pool root
I170510 10:08:24.421346 12 sql/session.go:653  [n1] txn: starting monitor, reserved 0 B, pool root
I170510 10:08:24.438021 131 storage/replica_command.go:2632  [split,n1,s1,r1/1:/M{in-ax}] initiating a split of this range at key /System/"" [r2]
I170510 10:08:24.438298 12 sql/planner.go:107  [log-event] internal-root: starting unlimited monitor
I170510 10:08:24.438334 12 sql/planner.go:113  [log-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.438377 12 sql/planner.go:119  [log-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.440024 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.440051 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.440082 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.441830 131 sql/mon/mem_usage.go:570  [split,n1,s1,r1/1:/M{in-ax}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.441870 131 sql/mon/mem_usage.go:528  [split,n1,s1,r1/1:/M{in-ax}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.442099 131 sql/mon/mem_usage.go:528  [split,n1,s1,r1/1:/M{in-ax}] internal-txn: now at 343 bytes (+343) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.442127 131 sql/mon/mem_usage.go:528  [split,n1,s1,r1/1:/M{in-ax}] internal-txn: now at 1423 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.442421 12 sql/mon/mem_usage.go:570  [n1] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.442445 12 sql/mon/mem_usage.go:528  [n1] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.442472 12 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 249 bytes (+249) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.442492 12 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 1313 bytes (+1064) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.453307 131 sql/mon/mem_usage.go:552  [split,n1,s1,r1/1:/M{in-ax}] internal-txn: now at 0 bytes (-1423) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.453333 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.453344 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.453361 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.453381 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.453391 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.453405 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.453415 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
E170510 10:08:24.461681 92 storage/replica_proposal.go:463  [n1,s1,r1/1:/M{in-ax}] could not load SystemConfig span: must retry later due to intent on SystemConfigSpan
I170510 10:08:24.462555 131 storage/split_queue.go:92  [split,n1,s1,r2/1:/{System/-Max}] splitting at key /System/tsd
I170510 10:08:24.462612 131 storage/replica_command.go:2632  [split,n1,s1,r2/1:/{System/-Max}] initiating a split of this range at key /System/tsd [r3]
I170510 10:08:24.465343 12 sql/mon/mem_usage.go:552  [n1] internal-txn: now at 0 bytes (-1313) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.465361 12 sql/planner.go:136  [log-event] internal-txn, memory usage max 1.3 KiB
I170510 10:08:24.465371 12 sql/mon/mem_usage.go:588  [log-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.465389 12 sql/mon/mem_usage.go:552  [log-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.465402 12 sql/planner.go:137  [log-event] internal-session, memory usage max 0 B
I170510 10:08:24.465419 12 sql/mon/mem_usage.go:588  [log-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.465429 12 sql/planner.go:138  [log-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.465438 12 sql/mon/mem_usage.go:588  [log-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.465689 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.465702 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.465723 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.466590 131 sql/mon/mem_usage.go:570  [split,n1,s1,r2/1:/{System/-Max}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.466620 131 sql/mon/mem_usage.go:528  [split,n1,s1,r2/1:/{System/-Max}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.466647 131 sql/mon/mem_usage.go:528  [split,n1,s1,r2/1:/{System/-Max}] internal-txn: now at 370 bytes (+370) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.466666 131 sql/mon/mem_usage.go:528  [split,n1,s1,r2/1:/{System/-Max}] internal-txn: now at 1450 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.467507 131 sql/mon/mem_usage.go:552  [split,n1,s1,r2/1:/{System/-Max}] internal-txn: now at 0 bytes (-1450) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.467523 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.467536 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.467554 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.467565 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.467576 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.467587 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.467595 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.469355 12 sql/event_log.go:101  [n1] Event: "alter_table", target: 12, info: {TableName:eventlog Statement:ALTER TABLE system.eventlog ALTER COLUMN uniqueid SET DEFAULT uuid_v4() User:node MutationID:0 CascadeDroppedViews:[]}
I170510 10:08:24.469377 12 sql/session.go:691  [n1] txn, memory usage max 0 B
I170510 10:08:24.469387 12 sql/mon/mem_usage.go:588  [n1] txn: releasing 0 bytes to the pool
I170510 10:08:24.471260 12 sql/planner.go:107  [leases-count] internal-root: starting unlimited monitor
I170510 10:08:24.471274 12 sql/planner.go:113  [leases-count] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.471285 12 sql/planner.go:119  [leases-count] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.473104 12 sql/mon/mem_usage.go:570  [n1] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.473128 12 sql/mon/mem_usage.go:528  [n1] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.473153 12 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 8 bytes (+8) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*groupNode).computeAggregates:448,sql.(*groupNode).Next:359
I170510 10:08:24.473174 12 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 1056 bytes (+1048) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*groupNode).computeAggregates:448
I170510 10:08:24.473196 12 sql/mon/mem_usage.go:552  [n1] internal-txn: now at 0 bytes (-1056) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*groupNode).Close:460
I170510 10:08:24.473216 12 sql/planner.go:136  [leases-count] internal-txn, memory usage max 1.0 KiB
I170510 10:08:24.473226 12 sql/mon/mem_usage.go:588  [leases-count] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.473243 12 sql/mon/mem_usage.go:552  [leases-count] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.473259 12 sql/planner.go:137  [leases-count] internal-session, memory usage max 0 B
I170510 10:08:24.473275 12 sql/mon/mem_usage.go:588  [leases-count] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.473285 12 sql/planner.go:138  [leases-count] internal-root, memory usage max 10 KiB
I170510 10:08:24.473294 12 sql/mon/mem_usage.go:588  [leases-count] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.473478 12 sql/lease.go:372  [n1] publish: descID=12 (eventlog) version=2 mtime=2017-05-10 10:08:24.473453159 +0200 CEST
I170510 10:08:24.474630 12 sql/planner.go:107  [leases-count] internal-root: starting unlimited monitor
I170510 10:08:24.474644 12 sql/planner.go:113  [leases-count] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.474655 12 sql/planner.go:119  [leases-count] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.475649 12 sql/mon/mem_usage.go:570  [n1] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.475679 12 sql/mon/mem_usage.go:528  [n1] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.475701 12 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 8 bytes (+8) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*groupNode).computeAggregates:448,sql.(*groupNode).Next:359
I170510 10:08:24.475752 12 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 1056 bytes (+1048) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*groupNode).computeAggregates:448
I170510 10:08:24.475776 12 sql/mon/mem_usage.go:552  [n1] internal-txn: now at 0 bytes (-1056) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*groupNode).Close:460
I170510 10:08:24.475790 12 sql/planner.go:136  [leases-count] internal-txn, memory usage max 1.0 KiB
I170510 10:08:24.475800 12 sql/mon/mem_usage.go:588  [leases-count] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.475817 12 sql/mon/mem_usage.go:552  [leases-count] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.475829 12 sql/planner.go:137  [leases-count] internal-session, memory usage max 0 B
I170510 10:08:24.475838 12 sql/mon/mem_usage.go:588  [leases-count] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.475848 12 sql/planner.go:138  [leases-count] internal-root, memory usage max 10 KiB
I170510 10:08:24.475857 12 sql/mon/mem_usage.go:588  [leases-count] internal-root: releasing 0 bytes to the pool
E170510 10:08:24.481776 106 storage/replica_proposal.go:463  [n1,s1,r2/1:/{System/-Max}] could not load SystemConfig span: must retry later due to intent on SystemConfigSpan
I170510 10:08:24.482586 131 storage/split_queue.go:92  [split,n1,s1,r3/1:/{System/tsd-Max}] splitting at key /System/"tse"
I170510 10:08:24.482625 131 storage/replica_command.go:2632  [split,n1,s1,r3/1:/{System/tsd-Max}] initiating a split of this range at key /System/"tse" [r4]
I170510 10:08:24.484838 12 sql/session.go:378  [n1] session, memory usage max 0 B
I170510 10:08:24.484851 12 sql/mon/mem_usage.go:588  [n1] session: releasing 0 bytes to the pool
I170510 10:08:24.484861 12 sql/session.go:379  [n1] root, memory usage max 0 B
I170510 10:08:24.484871 12 sql/mon/mem_usage.go:588  [n1] root: releasing 0 bytes to the pool
I170510 10:08:24.486553 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.486567 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.486578 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.487537 131 sql/mon/mem_usage.go:570  [split,n1,s1,r3/1:/{System/tsd-Max}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.487562 131 sql/mon/mem_usage.go:528  [split,n1,s1,r3/1:/{System/tsd-Max}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.487587 131 sql/mon/mem_usage.go:528  [split,n1,s1,r3/1:/{System/tsd-Max}] internal-txn: now at 374 bytes (+374) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.487606 131 sql/mon/mem_usage.go:528  [split,n1,s1,r3/1:/{System/tsd-Max}] internal-txn: now at 1454 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.488433 131 sql/mon/mem_usage.go:552  [split,n1,s1,r3/1:/{System/tsd-Max}] internal-txn: now at 0 bytes (-1454) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.488464 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.488475 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.488492 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.488502 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.488512 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.488522 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.488530 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.499964 131 storage/split_queue.go:92  [split,n1,s1,r4/1:/{System/tse-Max}] splitting at key /Table/0/0
I170510 10:08:24.499999 131 storage/replica_command.go:2632  [split,n1,s1,r4/1:/{System/tse-Max}] initiating a split of this range at key /Table/0 [r5]
I170510 10:08:24.504442 12 sql/session_mem_usage.go:126  [n1] root: starting unlimited monitor
I170510 10:08:24.504456 12 sql/session_mem_usage.go:135  [n1] session: starting monitor, reserved 0 B, pool root
I170510 10:08:24.504498 12 sql/session.go:653  [n1] txn: starting monitor, reserved 0 B, pool root
I170510 10:08:24.504552 12 sql/planner.go:107  [update-setting] internal-root: starting unlimited monitor
I170510 10:08:24.504563 12 sql/planner.go:113  [update-setting] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.504573 12 sql/planner.go:119  [update-setting] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.505489 12 sql/mon/mem_usage.go:570  [n1] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.505512 12 sql/mon/mem_usage.go:528  [n1] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.505531 12 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 106 bytes (+106) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.505559 12 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 1154 bytes (+1048) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.506255 12 sql/mon/mem_usage.go:552  [n1] internal-txn: now at 0 bytes (-1154) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.506272 12 sql/planner.go:136  [update-setting] internal-txn, memory usage max 1.1 KiB
I170510 10:08:24.506282 12 sql/mon/mem_usage.go:588  [update-setting] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.506302 12 sql/mon/mem_usage.go:552  [update-setting] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.506313 12 sql/planner.go:137  [update-setting] internal-session, memory usage max 0 B
I170510 10:08:24.506322 12 sql/mon/mem_usage.go:588  [update-setting] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.506333 12 sql/planner.go:138  [update-setting] internal-root, memory usage max 10 KiB
I170510 10:08:24.506357 12 sql/mon/mem_usage.go:588  [update-setting] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.507354 12 sql/session.go:691  [n1] txn, memory usage max 0 B
I170510 10:08:24.507367 12 sql/mon/mem_usage.go:588  [n1] txn: releasing 0 bytes to the pool
I170510 10:08:24.507380 12 sql/session.go:378  [n1] session, memory usage max 0 B
I170510 10:08:24.507389 12 sql/mon/mem_usage.go:588  [n1] session: releasing 0 bytes to the pool
I170510 10:08:24.507399 12 sql/session.go:379  [n1] root, memory usage max 0 B
I170510 10:08:24.507408 12 sql/mon/mem_usage.go:588  [n1] root: releasing 0 bytes to the pool
I170510 10:08:24.508649 12 server/server.go:853  [n1] done ensuring all necessary migrations have run
I170510 10:08:24.508672 12 server/server.go:855  [n1] serving sql connections
I170510 10:08:24.508749 12 cli/start.go:409  node startup completed:
CockroachDB node starting at 2017-05-10 10:08:24.508692604 +0200 CEST
build:      CCL 0f59bf400 @ 2017/05/06 17:13:15 (go1.8.1)
admin:      http://127.0.0.1:8080
sql:        postgresql://root@127.0.0.1:26257?sslmode=disable
logs:       /home/user/Temp/db1/cockroach-data/logs
store[0]:   path=/home/user/Temp/db1/cockroach-data
status:     initialized new cluster
clusterID:  1cf056a9-2ffc-402e-b68c-e873197b4168
nodeID:     1
I170510 10:08:24.511040 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.511054 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.511065 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.511982 131 sql/mon/mem_usage.go:570  [split,n1,s1,r4/1:/{System/tse-Max}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.512005 131 sql/mon/mem_usage.go:528  [split,n1,s1,r4/1:/{System/tse-Max}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.512031 131 sql/mon/mem_usage.go:528  [split,n1,s1,r4/1:/{System/tse-Max}] internal-txn: now at 366 bytes (+366) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.512050 131 sql/mon/mem_usage.go:528  [split,n1,s1,r4/1:/{System/tse-Max}] internal-txn: now at 1446 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.512774 131 sql/mon/mem_usage.go:552  [split,n1,s1,r4/1:/{System/tse-Max}] internal-txn: now at 0 bytes (-1446) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.512790 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.512808 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.512825 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.512836 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.512845 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.512856 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.512864 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.514151 356 sql/planner.go:107  [log-event] internal-root: starting unlimited monitor
I170510 10:08:24.514165 356 sql/planner.go:113  [log-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.514176 356 sql/planner.go:119  [log-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.515040 356 sql/mon/mem_usage.go:570  [n1] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.515064 356 sql/mon/mem_usage.go:528  [n1] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.515083 356 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 326 bytes (+326) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.515102 356 sql/mon/mem_usage.go:528  [n1] internal-txn: now at 1390 bytes (+1064) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.515923 356 sql/mon/mem_usage.go:552  [n1] internal-txn: now at 0 bytes (-1390) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.515940 356 sql/planner.go:136  [log-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.515950 356 sql/mon/mem_usage.go:588  [log-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.515967 356 sql/mon/mem_usage.go:552  [log-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.515990 356 sql/planner.go:137  [log-event] internal-session, memory usage max 0 B
I170510 10:08:24.516000 356 sql/mon/mem_usage.go:588  [log-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.516010 356 sql/planner.go:138  [log-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.516019 356 sql/mon/mem_usage.go:588  [log-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.516855 356 sql/event_log.go:101  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:{NetworkField:tcp AddressField:127.0.0.1:26257} Attrs: Locality:} ClusterID:1cf056a9-2ffc-402e-b68c-e873197b4168 StartedAt:1494403704412603959 LastUp:1494403704412603959}
I170510 10:08:24.527015 131 storage/split_queue.go:92  [split,n1,s1,r5/1:/{Table/0-Max}] splitting at key /Table/11/0
I170510 10:08:24.527081 131 storage/replica_command.go:2632  [split,n1,s1,r5/1:/{Table/0-Max}] initiating a split of this range at key /Table/11 [r6]
I170510 10:08:24.527993 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.528006 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.528017 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.528951 131 sql/mon/mem_usage.go:570  [split,n1,s1,r5/1:/{Table/0-Max}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.528981 131 sql/mon/mem_usage.go:528  [split,n1,s1,r5/1:/{Table/0-Max}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.529003 131 sql/mon/mem_usage.go:528  [split,n1,s1,r5/1:/{Table/0-Max}] internal-txn: now at 362 bytes (+362) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.529131 131 sql/mon/mem_usage.go:528  [split,n1,s1,r5/1:/{Table/0-Max}] internal-txn: now at 1442 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.537422 131 sql/mon/mem_usage.go:552  [split,n1,s1,r5/1:/{Table/0-Max}] internal-txn: now at 0 bytes (-1442) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.537459 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.537581 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.537617 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.537639 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.537659 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.537677 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.537692 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.542798 131 storage/split_queue.go:92  [split,n1,s1,r6/1:/{Table/11-Max}] splitting at key /Table/12/0
I170510 10:08:24.543289 131 storage/replica_command.go:2632  [split,n1,s1,r6/1:/{Table/11-Max}] initiating a split of this range at key /Table/12 [r7]
I170510 10:08:24.544506 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.544527 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.544551 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.546164 131 sql/mon/mem_usage.go:570  [split,n1,s1,r6/1:/{Table/11-Max}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.546223 131 sql/mon/mem_usage.go:528  [split,n1,s1,r6/1:/{Table/11-Max}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.546269 131 sql/mon/mem_usage.go:528  [split,n1,s1,r6/1:/{Table/11-Max}] internal-txn: now at 362 bytes (+362) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.546304 131 sql/mon/mem_usage.go:528  [split,n1,s1,r6/1:/{Table/11-Max}] internal-txn: now at 1442 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.547647 131 sql/mon/mem_usage.go:552  [split,n1,s1,r6/1:/{Table/11-Max}] internal-txn: now at 0 bytes (-1442) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.547673 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.547690 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.547727 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.547751 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.547766 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.547781 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.547793 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.560058 131 storage/split_queue.go:92  [split,n1,s1,r7/1:/{Table/12-Max}] splitting at key /Table/13/0
I170510 10:08:24.560087 131 storage/replica_command.go:2632  [split,n1,s1,r7/1:/{Table/12-Max}] initiating a split of this range at key /Table/13 [r8]
I170510 10:08:24.561488 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.561502 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.561513 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.562339 131 sql/mon/mem_usage.go:570  [split,n1,s1,r7/1:/{Table/12-Max}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.562362 131 sql/mon/mem_usage.go:528  [split,n1,s1,r7/1:/{Table/12-Max}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.562383 131 sql/mon/mem_usage.go:528  [split,n1,s1,r7/1:/{Table/12-Max}] internal-txn: now at 362 bytes (+362) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.562408 131 sql/mon/mem_usage.go:528  [split,n1,s1,r7/1:/{Table/12-Max}] internal-txn: now at 1442 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.563257 131 sql/mon/mem_usage.go:552  [split,n1,s1,r7/1:/{Table/12-Max}] internal-txn: now at 0 bytes (-1442) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.563274 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.563285 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.563302 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.563313 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.563322 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.563334 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.563342 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.566993 131 storage/split_queue.go:92  [split,n1,s1,r8/1:/{Table/13-Max}] splitting at key /Table/14/0
I170510 10:08:24.567021 131 storage/replica_command.go:2632  [split,n1,s1,r8/1:/{Table/13-Max}] initiating a split of this range at key /Table/14 [r9]
I170510 10:08:24.569094 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.569108 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.569124 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.570110 131 sql/mon/mem_usage.go:570  [split,n1,s1,r8/1:/{Table/13-Max}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.570133 131 sql/mon/mem_usage.go:528  [split,n1,s1,r8/1:/{Table/13-Max}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.570154 131 sql/mon/mem_usage.go:528  [split,n1,s1,r8/1:/{Table/13-Max}] internal-txn: now at 362 bytes (+362) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.570174 131 sql/mon/mem_usage.go:528  [split,n1,s1,r8/1:/{Table/13-Max}] internal-txn: now at 1442 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.570967 131 sql/mon/mem_usage.go:552  [split,n1,s1,r8/1:/{Table/13-Max}] internal-txn: now at 0 bytes (-1442) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.570984 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.570995 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.571012 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.571028 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.571038 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.571049 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.571059 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:24.574742 131 storage/split_queue.go:92  [split,n1,s1,r9/1:/{Table/14-Max}] splitting at key /Table/15/0
I170510 10:08:24.574769 131 storage/replica_command.go:2632  [split,n1,s1,r9/1:/{Table/14-Max}] initiating a split of this range at key /Table/15 [r10]
I170510 10:08:24.576787 131 sql/planner.go:107  [log-range-event] internal-root: starting unlimited monitor
I170510 10:08:24.576802 131 sql/planner.go:113  [log-range-event] internal-session: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.576813 131 sql/planner.go:119  [log-range-event] internal-txn: starting monitor, reserved 0 B, pool internal-root
I170510 10:08:24.577667 131 sql/mon/mem_usage.go:570  [split,n1,s1,r9/1:/{Table/14-Max}] internal-txn: requesting 10240 bytes from the pool
I170510 10:08:24.577690 131 sql/mon/mem_usage.go:528  [split,n1,s1,r9/1:/{Table/14-Max}] internal-root: now at 10240 bytes (+10240) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*MemoryMonitor).increaseBudget:573,sql/mon.(*MemoryMonitor).reserveMemory:500,sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491
I170510 10:08:24.577710 131 sql/mon/mem_usage.go:528  [split,n1,s1,r9/1:/{Table/14-Max}] internal-txn: now at 363 bytes (+363) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).AddRow:241,sql.(*valuesNode).Start:150,sql.(*editNodeRun).startEditNode:104
I170510 10:08:24.577728 131 sql/mon/mem_usage.go:528  [split,n1,s1,r9/1:/{Table/14-Max}] internal-txn: now at 1443 bytes (+1080) - sql/mon.(*MemoryMonitor).GrowAccount:391,sql/mon.(*BoundAccount).Grow:491,sql/sqlbase.(*RowContainer).allocChunks:196,sql/sqlbase.(*RowContainer).AddRow:251,sql.(*valuesNode).Start:150
I170510 10:08:24.578478 131 sql/mon/mem_usage.go:552  [split,n1,s1,r9/1:/{Table/14-Max}] internal-txn: now at 0 bytes (-1443) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*BoundAccount).Close:481,sql/sqlbase.(*RowContainer).Close:190,sql.(*valuesNode).Close:196,sql.(*insertNode).Close:300
I170510 10:08:24.578495 131 sql/planner.go:136  [log-range-event] internal-txn, memory usage max 1.4 KiB
I170510 10:08:24.578505 131 sql/mon/mem_usage.go:588  [log-range-event] internal-txn: releasing 10240 bytes to the pool
I170510 10:08:24.578522 131 sql/mon/mem_usage.go:552  [log-range-event] internal-root: now at 0 bytes (-10240) - sql/mon.(*MemoryMonitor).CloseAccount:404,sql/mon.(*MemoryMonitor).ClearAccount:410,sql/mon.(*MemoryMonitor).releaseBudget:590,sql/mon.(*MemoryMonitor).Stop:342,sql.finishInternalPlanner:136
I170510 10:08:24.578533 131 sql/planner.go:137  [log-range-event] internal-session, memory usage max 0 B
I170510 10:08:24.578542 131 sql/mon/mem_usage.go:588  [log-range-event] internal-session: releasing 0 bytes to the pool
I170510 10:08:24.578553 131 sql/planner.go:138  [log-range-event] internal-root, memory usage max 10 KiB
I170510 10:08:24.578561 131 sql/mon/mem_usage.go:588  [log-range-event] internal-root: releasing 0 bytes to the pool
I170510 10:08:25.185489 357 server/updates.go:231  [n1] A new version is available: 1.0.0-rc.2, details: https://www.cockroachlabs.com/docs/v1.0-rc.2.html
W170510 10:08:34.436811 141 server/status/runtime.go:184  [n1] unable to get file descriptor usage (will not try again): not implemented on openbsd
I170510 10:08:34.436881 141 server/status/runtime.go:225  [n1] runtime stats: 0 B RSS, 124 goroutines, 8.1 MiB/5.9 MiB/22 MiB GO alloc/idle/total, 0 B/0 B CGO alloc/total, 0.00cgo/sec, 0.00/0.00 %(u/s)time, 0.00 %gc (7x)
I170510 10:08:34.436979 139 storage/store.go:3996  [n1,s1] sstables (read amplification = 0):
I170510 10:08:34.473018 104 storage/replica_proposal.go:390  [n1,s1,r3/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 start=0.000000000,0 epo=1 pro=1494403714.472200802,0 following repl=(n1,s1):1 start=0.000000000,0 exp=1494403713.411453657,0 pro=1494403704.411475656,0
W170510 10:08:37.217837 517 server/server.go:600  [n1,client=127.0.0.1:35911] failed to set TCP keep-alive duration for pgwire: set tcp 127.0.0.1:26257->127.0.0.1:35911: protocol not available
I170510 10:08:37.217909 517 sql/mon/mem_usage.go:570  [n1,client=127.0.0.1:35911] conn: requesting 107520 bytes from the pool
I170510 10:08:37.217920 517 sql/mon/mem_usage.go:570  [n1,client=127.0.0.1:35911] sql: requesting 112640 bytes from the pool
E170510 10:08:37.217974 517 server/server.go:625  [n1,client=127.0.0.1:35911] unable to pre-allocate 21504 bytes for this connection: root: memory budget exceeded: 112640 bytes requested, 0 bytes in budget
I170510 10:08:43.132495 193 vendor/google.golang.org/grpc/transport/http2_server.go:323  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:26257->127.0.0.1:12226: use of closed network connection
I170510 10:08:43.132528 497 vendor/google.golang.org/grpc/transport/http2_server.go:323  transport: http2Server.HandleStreams failed to read frame: read tcp 127.0.0.1:26257->127.0.0.1:3772: use of closed network connection
I170510 10:08:43.133128 546 storage/engine/rocksdb.go:446  closing rocksdb instance at "/home/user/Temp/db1/cockroach-data"
@knz
Copy link
Contributor

knz commented May 10, 2017 •
edited
Loading

This is the line that proves gosigar did not report the amount of free memory available:

I170510 10:08:24.357727 12 server/server.go:268  root: starting monitor, reserved 0 B, pool (none)

On a working gosigar implementation here is an example output:

I170510 09:51:44.738703 15 server/server.go:262  root: starting monitor, reserved 1.9 GiB, pool (none)

I think you can work around this by specifying manually --max-sql-memory on the start command line.

Also since gosigar does not work properly, you should specify --cache too, otherwise your db performance will be very poor.

@knz
Copy link
Contributor

knz commented May 10, 2017

Can you try this out and report your results?

@knz knz mentioned this issue May 10, 2017
Closed
@knz
Copy link
Contributor

knz commented May 10, 2017

@mrijkeboer I also filed #15839. If you feel like it a contribution to fix that issue would be welcome!

@mrijkeboer
Copy link
Author

@knz when I add --max-sql-memory=1GiB --cache=1GiB I can connect, so you're right.

On a similar note, I also see the following in my log (probably also gosigar related):

W170510 12:18:29.023393 143 server/status/runtime.go:184  [n1] unable to get file descriptor usage (will not try again): not implemented on openbsd

With regards to #15839, I have never programmed in Go and I'm currently on a very tight schedule, so I don't have the time available to dive into Go.

@knz
Copy link
Contributor

knz commented May 10, 2017

The issue with file descriptors is a separate issue, I haven't looked into that. There are two mechanisms (one more next to gosigar) for managing the file descriptors, perhaps both need tweaking.

Thanks for reporting the issue anyway. I'm glad the workaround helped!

@mrijkeboer
Copy link
Author

@knz Do you want me to open a github issue for the file descriptor issue?

@mrijkeboer
Copy link
Author

@knz What would be recommended values (% of main memory) for --max-sql-memory and --cache?

@knz
Copy link
Contributor

knz commented May 10, 2017

Please file a separate issue for the file descriptor issue, and mention there how you had to adjust with sysctl to get it working.

The defaults for --max-sql-memory and --cache are each 25% of total physical RAM. These are safe values for you to use (or anything lower than that). We recommend a minimum of 512MB for each.

@knz knz changed the title Can't connect to cluster on OpenBSD sql: zero SQL mem pool on OpenBSD prevents clients from connecting May 10, 2017
@knz knz added C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. O-community Originated from the community E-easy Easy issue to tackle, requires little or no CockroachDB experience labels May 10, 2017
@knz knz added this to the Later milestone May 10, 2017
@mrijkeboer
Copy link
Author

@knz I just filed #15840 for the file descriptor issue.

@knz knz mentioned this issue May 10, 2017
Open
@knz
Copy link
Contributor

knz commented Sep 3, 2017

This is obsoleted by #18040.

@knz knz closed this as completed Sep 3, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-bug Code not up to spec/doc, specs & docs deemed correct. Solution expected to change code/behavior. E-easy Easy issue to tackle, requires little or no CockroachDB experience O-community Originated from the community
Projects
None yet
Milestone
Later
Development

No branches or pull requests
2 participants
@mrijkeboer @knz