CockroachDB gets locked up

[bra-fsn]

Describe the problem

Starting with an empty database and putting a test load onto the single node CockroachDB instance, after running for some minutes, it gets locked up.
No queries are answered, it does no disk IO, but eats two cores completely:

  PID USERNAME    THR PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
30691 root         46  37    0  1412M   643M uwait    9  25.8H 200.00% cockroach

To Reproduce

1. built 38a4cbe from source on FreeBSD 12 with go1.14/Clang 9.0.1
2. started a single node with ./cockroach start --insecure "--store=path=/data/cockroachtest,rocksdb=compaction_readahead_size=4M" --listen-addr=$ip --http-addr=localhost:8080 --log-dir=/data/crdb/log
3. created the required DB/tables
4. started the test load

The node doesn't even respond to HTTP commands, so I can't get any info from there.

**Additional data / screenshots** Doing a trace on the process, it seems it does these endlessly:

 30691 cockroach CALL  sigreturn(0xc0009576c0)
 30691 cockroach RET   sigreturn JUSTRETURN
 30691 cockroach PSIG  SIGURG caught handler=0x806706850 mask=0x0 code=SI_NOINFO
 30691 cockroach CALL  sigprocmask(SIG_SETMASK,0xc000957a8c,0)
 30691 cockroach RET   sigprocmask 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
[...]
 30691 cockroach CALL  sigreturn(0xc0009576c0)
 30691 cockroach RET   sigreturn JUSTRETURN
 30691 cockroach PSIG  SIGURG caught handler=0x806706850 mask=0x0 code=SI_LWP
 30691 cockroach CALL  sigprocmask(SIG_SETMASK,0xc000957a8c,0)
 30691 cockroach RET   sigprocmask 0
 30691 cockroach CALL  thr_kill(0x18aef,SIGURG)
 30691 cockroach RET   thr_kill 0
[...]
 30691 cockroach RET   nanosleep 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach CALL  _umtx_op(0xc00751bd50,UMTX_OP_WAKE_PRIVATE,0x1,0,0)
 30691 cockroach RET   _umtx_op 0
 30691 cockroach CALL  thr_kill(0x18af5,SIGURG)
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach PSIG  SIGURG caught handler=0x806706850 mask=0x0 code=SI_NOINFO
 30691 cockroach RET   thr_kill 0
 30691 cockroach CALL  thr_kill(0x18aef,SIGURG)
 30691 cockroach RET   thr_kill 0
 30691 cockroach CALL  nanosleep(0x7fffdfffde80,0)
 30691 cockroach RET   _umtx_op 0
 30691 cockroach CALL  _umtx_op(0xc00751bd50,UMTX_OP_WAIT_UINT_PRIVATE,0,0x18,0)
 30691 cockroach CALL  sigprocmask(SIG_SETMASK,0xc000a33a8c,0)
 30691 cockroach RET   sigprocmask 0
 30691 cockroach CALL  sigreturn(0xc000a336c0)
 30691 cockroach RET   sigreturn JUSTRETURN
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach CALL  sigreturn(0xc0009576c0)
 30691 cockroach RET   sigreturn JUSTRETURN
 30691 cockroach PSIG  SIGURG caught handler=0x806706850 mask=0x0 code=SI_NOINFO
 30691 cockroach CALL  sigprocmask(SIG_SETMASK,0xc000957a8c,0)
 30691 cockroach CALL  thr_kill(0x18aef,SIGURG)
 30691 cockroach RET   thr_kill 0
 30691 cockroach RET   sigprocmask 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
 30691 cockroach CALL  sched_yield
 30691 cockroach RET   sched_yield 0
[...]

The two threads eating the CPUs are:

   THR USERNAME    PRI NICE   SIZE    RES STATE    C   TIME    WCPU COMMAND
101103 root        103    0  1412M   806M CPU11   11 756:56 100.00% cockroach{cockroach}
101109 root        103    0  1412M   806M CPU16   16 756:11 100.00% cockroach{cockroach}

I did a coredump and started gdb to see what are those:

  16   LWP 101109        runtime.procyield ()
    at /usr/local/go/src/runtime/asm_amd64.s:570
  15   LWP 101103        0x00000000041df560 in github.com/cockroachdb/cockroach/pkg/sql/parser.(*sqlParserImpl).Parse (sqlrcvr=0xc004e7f738, sqllex=..., 
    ~r1=<optimized out>) at yaccpar:195

Switching to 15 and doing a backtrace gives:

(gdb) thread 15
[Switching to thread 15 (LWP 101103)]
#0  0x00000000041df560 in github.com/cockroachdb/cockroach/pkg/sql/parser.(*sqlParserImpl).Parse (sqlrcvr=0xc004e7f738, sqllex=..., ~r1=<optimized out>)
    at yaccpar:195
195	yaccpar: No such file or directory.
(gdb) bt
#0  0x00000000041df560 in github.com/cockroachdb/cockroach/pkg/sql/parser.(*sqlParserImpl).Parse (sqlrcvr=0xc004e7f738, sqllex=..., ~r1=<optimized out>)
    at yaccpar:195
#1  0x000000000416e66c in github.com/cockroachdb/cockroach/pkg/sql/parser.(*Parser).parse (p=0xc004e7f6a0, depth=<optimized out>, sql=..., tokens=..., 
    nakedIntType=0x66a80a0 <github.com/cockroachdb/cockroach/pkg/sql/types..stmp_18>, ~r4=..., ~r5=...)
    at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/sql/parser/parse.go:176
#2  0x000000000416e283 in github.com/cockroachdb/cockroach/pkg/sql/parser.(*Parser).parseWithDepth (p=0xc004e7f6a0, depth=1, sql=..., 
    nakedIntType=0x66a80a0 <github.com/cockroachdb/cockroach/pkg/sql/types..stmp_18>, ~r3=..., ~r4=...)
    at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/sql/parser/parse.go:156
#3  0x0000000005cf731a in github.com/cockroachdb/cockroach/pkg/sql/parser.(*Parser).ParseWithInt (p=<optimized out>, sql=..., 
    nakedIntType=0x66a80a0 <github.com/cockroachdb/cockroach/pkg/sql/types..stmp_18>)
    at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/sql/parser/parse.go:103
#4  github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).handleSimpleQuery (
    c=0xc004e7f600, ctx=..., buf=0xc004e7fdd0, timeReceived=..., 
--Type <RET> for more, q to quit, c to continue without paging--
    ize=0x66a80a0 <github.com/cockroachdb/cockroach/pkg/sql/types..stmp_18>, ~r4=...) at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:686
#5  0x0000000005cf5aff in github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*conn).serveImpl (c=0xc004e7f600, ctx=..., draining={void (bool *)} 0xc00362fb90, sqlServer=0xc001412000, reserved=..., authOpt=..., 
    stopper=<optimized out>) at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:378
#6  0x0000000005cf486d in github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).serveConn (s=0xc0006ff680, ctx=..., netConn=..., sArgs=..., reserved=..., authOpt=...)
    at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:156
#7  0x0000000005d00e3f in github.com/cockroachdb/cockroach/pkg/sql/pgwire.(*Server).ServeConn (s=0xc0006ff680, ctx=..., conn=..., socketType=true, ~r3=...)
    at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/sql/pgwire/server.go:582
#8  0x0000000005d7ff6d in github.com/cockroachdb/cockroach/pkg/server.(*Server).startServeSQL.func1.1 (conn=...) at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/server/server.go:2240
#9  0x0000000003fea67f in github.com/cockroachdb/cockroach/pkg/util/netutil.(*Server).ServeWith.func1 (stopper=0xc0001106c0, ctx=..., s=0xc000ab6520, rw=..., serveConn={void (net.Conn)} 0xc00362ffd8)
    at /home/bra/go/src/github.com/cockroachdb/cockroach/pkg/util/netutil/net.go:147
#10 0x000000000353f831 in runtime.goexit () at /usr/local/go/src/runtime/asm_amd64.s:1373
#11 0x000000c0001106c0 in ?? ()
#12 0x00000000015b1da0 in ?? ()
#13 0x000000c000d2cd80 in ?? ()
#14 0x000000c000ab6520 in ?? ()
#15 0x00000000015ff980 in ?? ()
#16 0x000000c006133800 in ?? ()
#17 0x000000c000d2cdb0 in ?? ()
#18 0x0000000000000000 in ?? ()

The other one is:

(gdb) thread 16
[Switching to thread 16 (LWP 101109)]
#0  runtime.procyield () at /usr/local/go/src/runtime/asm_amd64.s:570
570		SUBL	$1, AX
(gdb) bt
#0  runtime.procyield () at /usr/local/go/src/runtime/asm_amd64.s:570
#1  0x000000000350de4f in runtime.suspendG (gp=0xc0040dd380, ~r1=...) at /usr/local/go/src/runtime/preempt.go:248
#2  0x000000000353a976 in runtime.markroot.func1 () at /usr/local/go/src/runtime/mgcmark.go:218
#3  0x00000000034f6963 in runtime.markroot (gcw=0xc000085e98, i=665) at /usr/local/go/src/runtime/mgcmark.go:199
#4  0x00000000034f8327 in runtime.gcDrain (gcw=0xc000085e98, flags=2) at /usr/local/go/src/runtime/mgcmark.go:999
#5  0x000000000353a86e in runtime.gcBgMarkWorker.func2 () at /usr/local/go/src/runtime/mgc.go:1951
#6  0x000000000353d796 in runtime.systemstack () at /usr/local/go/src/runtime/asm_amd64.s:370
#7  0x00000000035122b0 in ?? () at <autogenerated>:1
#8  0x0000000807400140 in ?? ()
#9  0x0000000000200000 in ?? ()
#10 0x0000000000000000 in ?? ()

The thread (LWP) ids seem to be constant, so these two threads have an endless loop.

Goroutines:

(gdb) info goroutines
  1 waiting  runtime.gopark
  2 waiting  runtime.gopark
  3 waiting  runtime.gopark
  4 waiting  runtime.gopark
  5 waiting  runtime.gopark
  6 waiting  runtime.gopark
* 18 waiting  runtime.systemstack_switch
  19 waiting  runtime.gopark
  20 waiting  runtime.gopark
  34 waiting  runtime.gopark
  21 waiting  runtime.gopark
  22 waiting  runtime.gopark
  7 waiting  runtime.gopark
  35 waiting  runtime.gopark
  36 waiting  runtime.gopark
  50 waiting  runtime.gopark
  51 waiting  runtime.gopark
  8 waiting  runtime.gopark
  52 waiting  runtime.gopark
  9 waiting  runtime.gopark
  37 waiting  runtime.gopark
  53 waiting  runtime.gopark
  23 waiting  runtime.gopark
  24 waiting  runtime.gopark
  25 waiting  runtime.gopark
  10 waiting  runtime.gopark
  11 waiting  runtime.gopark
* 38 syscall  runtime.systemstack_switch
  39 waiting  runtime.gopark
  15 waiting  runtime.gopark
  13 waiting  runtime.gopark
  40 waiting  runtime.gopark
  66 waiting  runtime.gopark
  67 waiting  runtime.gopark
  68 waiting  runtime.gopark
  71 waiting  runtime.gopark
  72 waiting  runtime.gopark
  30 waiting  runtime.gopark
  16 waiting  runtime.gopark
  82 waiting  runtime.gopark
  83 waiting  runtime.gopark
  84 waiting  runtime.gopark
  85 waiting  runtime.gopark
  86 waiting  runtime.gopark
  87 waiting  runtime.gopark
  88 waiting  runtime.gopark
  89 waiting  runtime.gopark
  90 waiting  runtime.gopark
  91 waiting  runtime.gopark
  92 waiting  runtime.gopark
  93 waiting  runtime.gopark
  94 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  95 waiting  runtime.gopark
  96 waiting  runtime.gopark
  97 waiting  runtime.gopark
  98 waiting  runtime.gopark
  99 waiting  runtime.gopark
  100 waiting  runtime.gopark
  114 waiting  runtime.gopark
  115 waiting  runtime.gopark
  116 waiting  runtime.gopark
  117 waiting  runtime.gopark
  118 waiting  runtime.gopark
  119 waiting  runtime.gopark
  31 waiting  runtime.gopark
  32 waiting  runtime.gopark
  33 waiting  runtime.gopark
  121 waiting  runtime.gopark
  131 waiting  runtime.gopark
  132 waiting  runtime.gopark
  54 waiting  runtime.gopark
  55 waiting  runtime.gopark
  56 waiting  runtime.gopark
  146 waiting  runtime.gopark
  147 waiting  runtime.gopark
  148 waiting  runtime.gopark
  133 waiting  runtime.gopark
  134 waiting  runtime.gopark
  135 waiting  runtime.gopark
  101 waiting  runtime.gopark
  41 waiting  runtime.gopark
  14544 waiting  runtime.gopark
  43 waiting  runtime.gopark
  44 waiting  runtime.gopark
  45 waiting  runtime.gopark
  46 waiting  runtime.gopark
  102 waiting  runtime.gopark
  103 waiting  runtime.gopark
  104 waiting  runtime.gopark
  105 waiting  runtime.gopark
  106 waiting  runtime.gopark
  107 waiting  runtime.gopark
  108 waiting  runtime.gopark
  109 waiting  runtime.gopark
  110 waiting  runtime.gopark
  111 waiting  runtime.gopark
  112 waiting  runtime.gopark
  113 waiting  runtime.gopark
  162 waiting  runtime.gopark
  163 waiting  runtime.gopark
  164 waiting  runtime.gopark
  165 waiting  runtime.gopark
  166 waiting  runtime.gopark
  167 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  168 waiting  runtime.gopark
  169 waiting  runtime.gopark
  170 waiting  runtime.gopark
  171 waiting  runtime.gopark
  172 waiting  runtime.gopark
  173 waiting  runtime.gopark
  174 waiting  runtime.gopark
  175 waiting  runtime.gopark
  176 waiting  runtime.gopark
  177 waiting  runtime.gopark
  178 waiting  runtime.gopark
  179 waiting  runtime.gopark
  180 waiting  runtime.gopark
  181 waiting  runtime.gopark
  182 waiting  runtime.gopark
  183 waiting  runtime.gopark
  184 waiting  runtime.gopark
  185 waiting  runtime.gopark
  186 waiting  runtime.gopark
  187 waiting  runtime.gopark
  188 waiting  runtime.gopark
  189 waiting  runtime.gopark
  190 waiting  runtime.gopark
  191 waiting  runtime.gopark
  192 waiting  runtime.gopark
  193 waiting  runtime.gopark
  194 waiting  runtime.gopark
  195 waiting  runtime.gopark
  196 waiting  runtime.gopark
  197 waiting  runtime.gopark
  198 waiting  runtime.gopark
  199 waiting  runtime.gopark
  200 waiting  runtime.gopark
  201 waiting  runtime.gopark
  202 waiting  runtime.gopark
  203 waiting  runtime.gopark
  204 waiting  runtime.gopark
  205 waiting  runtime.gopark
  206 waiting  runtime.gopark
  207 waiting  runtime.gopark
  208 waiting  runtime.gopark
  209 waiting  runtime.gopark
  210 waiting  runtime.gopark
  211 waiting  runtime.gopark
  212 waiting  runtime.gopark
  213 waiting  runtime.gopark
  214 waiting  runtime.gopark
  215 waiting  runtime.gopark
  216 waiting  runtime.gopark
  217 waiting  runtime.gopark
  218 waiting  runtime.gopark
  219 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  220 waiting  runtime.gopark
  221 waiting  runtime.gopark
  222 waiting  runtime.gopark
  223 waiting  runtime.gopark
  224 waiting  runtime.gopark
  225 waiting  runtime.gopark
  226 waiting  runtime.gopark
  227 waiting  runtime.gopark
  228 waiting  runtime.gopark
  229 waiting  runtime.gopark
  230 waiting  runtime.gopark
  231 waiting  runtime.gopark
  232 waiting  runtime.gopark
  233 waiting  runtime.gopark
  234 waiting  runtime.gopark
  235 waiting  runtime.gopark
  236 waiting  runtime.gopark
  237 waiting  runtime.gopark
  238 waiting  runtime.gopark
  239 waiting  runtime.gopark
  240 waiting  runtime.gopark
  241 waiting  runtime.gopark
  242 waiting  runtime.gopark
  243 waiting  runtime.gopark
  244 waiting  runtime.gopark
  245 waiting  runtime.gopark
  246 waiting  runtime.gopark
  247 waiting  runtime.gopark
  248 waiting  runtime.gopark
  249 waiting  runtime.gopark
  250 waiting  runtime.gopark
  251 waiting  runtime.gopark
  252 waiting  runtime.gopark
  253 waiting  runtime.gopark
  254 waiting  runtime.gopark
  255 waiting  runtime.gopark
  256 waiting  runtime.gopark
  257 waiting  runtime.gopark
  258 waiting  runtime.gopark
  259 waiting  runtime.gopark
  260 waiting  runtime.gopark
  261 waiting  runtime.gopark
  262 waiting  runtime.gopark
  263 waiting  runtime.gopark
  264 waiting  runtime.gopark
  265 waiting  runtime.gopark
  266 waiting  runtime.gopark
  267 waiting  runtime.gopark
  268 waiting  runtime.gopark
  269 waiting  runtime.gopark
  270 waiting  runtime.gopark
  271 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  272 waiting  runtime.gopark
  273 waiting  runtime.gopark
  274 waiting  runtime.gopark
  275 waiting  runtime.gopark
  276 waiting  runtime.gopark
  277 waiting  runtime.gopark
  278 waiting  runtime.gopark
  279 waiting  runtime.gopark
  280 waiting  runtime.gopark
  281 waiting  runtime.gopark
  282 waiting  runtime.gopark
  283 waiting  runtime.gopark
  284 waiting  runtime.gopark
  285 waiting  runtime.gopark
  286 waiting  runtime.gopark
  287 waiting  runtime.gopark
  288 waiting  runtime.gopark
  289 waiting  runtime.gopark
  290 waiting  runtime.gopark
  291 waiting  runtime.gopark
  292 waiting  runtime.gopark
  293 waiting  runtime.gopark
  294 waiting  runtime.gopark
  295 waiting  runtime.gopark
  296 waiting  runtime.gopark
  297 waiting  runtime.gopark
  298 waiting  runtime.gopark
  299 waiting  runtime.gopark
  300 waiting  runtime.gopark
  301 waiting  runtime.gopark
  302 waiting  runtime.gopark
  303 waiting  runtime.gopark
  304 waiting  runtime.gopark
  305 waiting  runtime.gopark
  306 waiting  runtime.gopark
  307 waiting  runtime.gopark
  308 waiting  runtime.gopark
  309 waiting  runtime.gopark
  310 waiting  runtime.gopark
  311 waiting  runtime.gopark
  312 waiting  runtime.gopark
  313 waiting  runtime.gopark
  314 waiting  runtime.gopark
  315 waiting  runtime.gopark
  316 waiting  runtime.gopark
  318 waiting  runtime.gopark
  319 waiting  runtime.gopark
  320 waiting  runtime.gopark
  321 waiting  runtime.gopark
  322 waiting  runtime.gopark
  338 waiting  runtime.gopark
  339 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  340 waiting  runtime.gopark
  341 waiting  runtime.gopark
  342 waiting  runtime.gopark
  343 waiting  runtime.gopark
  344 waiting  runtime.gopark
  345 waiting  runtime.gopark
  346 waiting  runtime.gopark
  347 waiting  runtime.gopark
  323 waiting  runtime.gopark
  324 waiting  runtime.gopark
  325 waiting  runtime.gopark
  326 waiting  runtime.gopark
  327 waiting  runtime.gopark
  328 waiting  runtime.gopark
  329 waiting  runtime.gopark
  330 waiting  runtime.gopark
  331 waiting  runtime.gopark
  332 waiting  runtime.gopark
  333 waiting  runtime.gopark
  334 waiting  runtime.gopark
  335 waiting  runtime.gopark
  47 waiting  runtime.gopark
  6593336 waiting  runtime.gopark
  351 waiting  runtime.gopark
  376 waiting  runtime.gopark
  377 waiting  runtime.gopark
  378 waiting  runtime.gopark
  379 waiting  runtime.gopark
  380 waiting  runtime.gopark
  381 waiting  runtime.gopark
  382 waiting  runtime.gopark
  383 waiting  runtime.gopark
  384 waiting  runtime.gopark
  14506 waiting  runtime.gopark
  14514 waiting  runtime.gopark
  14542 waiting  runtime.gopark
  6592881 waiting  runtime.gopark
  1189 waiting  runtime.gopark
  14532 waiting  runtime.gopark
  6593376 waiting  runtime.gopark
  14509 waiting  runtime.gopark
  1070 waiting  runtime.gopark
  6592118 waiting  runtime.gopark
  6593016 waiting  runtime.gopark
  6591523 waiting  runtime.gopark
  6592685 waiting  runtime.gopark
  6592408 waiting  runtime.gopark
  6593706 waiting  runtime.gopark
  6593774 waiting  runtime.gopark
  6591751 waiting  runtime.gopark
  6592374 waiting  runtime.gopark
  14499 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  6593134 waiting  runtime.gopark
  6593297 waiting  runtime.gopark
  6592978 waiting  runtime.gopark
  6592705 waiting  runtime.gopark
  6592755 waiting  runtime.gopark
  6593215 waiting  runtime.gopark
  6591857 waiting  runtime.gopark
  14524 waiting  runtime.gopark
  6592902 waiting  runtime.gopark
  1432 waiting  runtime.gopark
  14517 waiting  runtime.gopark
  6592688 waiting  runtime.gopark
  14541 waiting  runtime.gopark
  737 waiting  runtime.gopark
  6591490 waiting  runtime.gopark
  1187 waiting  runtime.gopark
  6592533 waiting  runtime.gopark
  14530 waiting  runtime.gopark
  6593140 waiting  runtime.gopark
  14500 waiting  runtime.gopark
  14545 waiting  runtime.gopark
  6592073 waiting  runtime.gopark
  14526 waiting  runtime.gopark
  14511 waiting  runtime.gopark
  6592471 waiting  runtime.gopark
  6593425 waiting  runtime.gopark
  6593206 waiting  runtime.gopark
  6593583 waiting  runtime.gopark
  6592403 waiting  runtime.gopark
  6591794 waiting  runtime.gopark
  6593973 waiting  runtime.gopark
  6593765 waiting  runtime.gopark
  14536 waiting  runtime.gopark
  6591628 waiting  runtime.gopark
  6593318 waiting  runtime.gopark
  1188 waiting  runtime.gopark
  14521 waiting  runtime.gopark
  1138 waiting  runtime.gopark
  14538 waiting  runtime.gopark
  6592416 waiting  runtime.gopark
  6594057 waiting  runtime.gopark
  14520 waiting  runtime.gopark
  1053 waiting  runtime.gopark
  1052 waiting  runtime.gopark
  990 waiting  runtime.gopark
  1051 waiting  runtime.gopark
  991 waiting  runtime.gopark
* 14508 running  runtime.systemstack_switch
  14539 waiting  runtime.gopark
  6592723 waiting  runtime.gopark
  6592582 waiting  runtime.gopark
  6592410 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  14503 waiting  runtime.gopark
  6592528 waiting  runtime.gopark
  6591952 waiting  runtime.gopark
  6593377 waiting  runtime.gopark
  6593959 waiting  runtime.gopark
  6592164 waiting  runtime.gopark
  14533 waiting  runtime.gopark
  6591647 waiting  runtime.gopark
  6591635 waiting  runtime.gopark
  14512 waiting  runtime.gopark
  6593190 waiting  runtime.gopark
  14523 waiting  runtime.gopark
  6591972 waiting  runtime.gopark
  6593802 waiting  runtime.gopark
  6592236 waiting  runtime.gopark
  14502 waiting  runtime.gopark
  6591702 waiting  runtime.gopark
  14505 waiting  runtime.gopark
  6592919 waiting  runtime.gopark
  14518 waiting  runtime.gopark
  6591822 waiting  runtime.gopark
  14527 waiting  runtime.gopark
  6593196 waiting  runtime.gopark
  14515 waiting  runtime.gopark
  14535 waiting  runtime.gopark
  14529 waiting  runtime.gopark
  6593610 waiting  runtime.gopark
  6591897 waiting  runtime.gopark
  6592113 waiting  runtime.gopark
  6592741 waiting  runtime.gopark
  6593843 waiting  runtime.gopark
  6592506 waiting  runtime.gopark
  6592074 waiting  runtime.gopark
  6593114 waiting  runtime.gopark
  6593015 waiting  runtime.gopark
  6592747 waiting  runtime.gopark
  6591771 waiting  runtime.gopark
  6592203 waiting  runtime.gopark
  6591567 waiting  runtime.gopark
  6592319 waiting  runtime.gopark
  6592003 waiting  runtime.gopark
  6592179 waiting  runtime.gopark
  6593426 waiting  runtime.gopark
  6591624 waiting  runtime.gopark
  6592631 waiting  runtime.gopark
  6593447 waiting  runtime.gopark
  6592274 waiting  runtime.gopark
  6591881 waiting  runtime.gopark
  6593705 waiting  runtime.gopark
  6591683 waiting  runtime.gopark
  6593124 waiting  runtime.gopark
  6592389 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  6593304 waiting  runtime.gopark
  6593364 waiting  runtime.gopark
  6593135 waiting  runtime.gopark
  6591689 waiting  runtime.gopark
  6593468 waiting  runtime.gopark
  6592339 waiting  runtime.gopark
  6593556 waiting  runtime.gopark
  6591964 waiting  runtime.gopark
  6593801 waiting  runtime.gopark
  6591893 waiting  runtime.gopark
  6593885 waiting  runtime.gopark
  6592286 waiting  runtime.gopark
  6593320 waiting  runtime.gopark
  6593724 waiting  runtime.gopark
  6593197 waiting  runtime.gopark
  6591801 waiting  runtime.gopark
  6593927 waiting  runtime.gopark
  6593366 waiting  runtime.gopark
  6592032 waiting  runtime.gopark
  6593856 waiting  runtime.gopark
  6593647 waiting  runtime.gopark
  6591682 waiting  runtime.gopark
  6592170 waiting  runtime.gopark
  6591688 waiting  runtime.gopark
  6592934 waiting  runtime.gopark
  6592614 waiting  runtime.gopark
  6593689 waiting  runtime.gopark
  6594026 waiting  runtime.gopark
  6594025 waiting  runtime.gopark
  6592618 waiting  runtime.gopark
  6591971 waiting  runtime.gopark
  6592536 waiting  runtime.gopark
  6592287 waiting  runtime.gopark
  6591666 waiting  runtime.gopark
  6592388 waiting  runtime.gopark
  6593102 waiting  runtime.gopark
  6592678 waiting  runtime.gopark
  6592835 waiting  runtime.gopark
  6592590 waiting  runtime.gopark
  6593737 waiting  runtime.gopark
  6593321 waiting  runtime.gopark
  6594010 waiting  runtime.gopark
  6591744 waiting  runtime.gopark
  6593798 waiting  runtime.gopark
  6593615 waiting  runtime.gopark
  6591554 waiting  runtime.gopark
  6593754 waiting  runtime.gopark
  6593789 waiting  runtime.gopark
  6591643 waiting  runtime.gopark
  6593894 waiting  runtime.gopark
  6592034 waiting  runtime.gopark
  6591745 waiting  runtime.gopark
--Type <RET> for more, q to quit, c to continue without paging--
  6592836 waiting  runtime.gopark
  6592381 waiting  runtime.gopark
  6593701 waiting  runtime.gopark
  6591930 waiting  runtime.gopark
  6593207 waiting  runtime.gopark
  6593379 waiting  runtime.gopark
  6591491 waiting  runtime.gopark
  6593764 waiting  runtime.gopark
  6593424 waiting  runtime.gopark
  6591899 waiting  runtime.gopark
  6593298 waiting  runtime.gopark
  6592821 waiting  runtime.gopark
  6593611 waiting  runtime.gopark
  6592397 waiting  runtime.gopark
  6591904 waiting  runtime.gopark
  6593866 waiting  runtime.gopark
  6591743 waiting  runtime.gopark
  6592730 waiting  runtime.gopark
  6594038 waiting  runtime.gopark
  6593470 waiting  runtime.gopark
  6591883 waiting  runtime.gopark
  6593163 waiting  runtime.gopark
  6592539 waiting  runtime.gopark
  6591441 waiting  runtime.gopark
  6593427 waiting  runtime.gopark
  6592099 waiting  runtime.gopark
  6591733 waiting  runtime.gopark
  6593019 waiting  runtime.gopark
  6592271 waiting  runtime.gopark
  6593070 waiting  runtime.gopark
  6593386 waiting  runtime.gopark
  6591790 waiting  runtime.gopark
  6593049 waiting  runtime.gopark
  6592266 waiting  runtime.gopark
  6593139 waiting  runtime.gopark
  6592585 waiting  runtime.gopark
  6592065 waiting  runtime.gopark
  6591953 waiting  runtime.gopark
  6592490 waiting  runtime.gopark

Environment:

# ./cockroach version
Build Tag:    v20.1.0-beta.4-555-g38a4cbe92e
Build Time:   2020/04/18 21:08:38
Distribution: CCL
Platform:     freebsd amd64 (x86_64-unknown-freebsd12.1)
Go Version:   go1.14
C Compiler:   FreeBSD Clang 9.0.1 (git@github.com:llvm/llvm-project.git c1a0a213378a458fbea1a5c77b315c7dce08fd05)
Build SHA-1:  38a4cbe92e343f5b8e9d8cbda2d279fff3561c8f
Build Type:   development

I'm not doing anything new, this workload could run of days previously. I've upgraded the server yesterday, so it may be the cause.

[tbg]

Hi @bra-fsn, thanks for the report. It's suspicious that the HTTP endpoints don't even respond.

If you stop the test load, does it recover?

Assuming it doesn't, can you let it sit for a while (without the load) and then kill -QUIT the process? That should produce a goroutine dump, which I'd then ask you to provide (for example via https://gist.github.com/).

[bra-fsn]

Sorry, I've already stopped the server. I'll try to reproduce this again.

[bra-fsn]

I could reproduce this second time flawlessly, so I hope I can help with data to debug this.
To answer the question: no, removing the load doesn't make it recover.
Sending QUIT doesn't seem to produce anything, I couldn't find a new file in log/goroutine_dump.
BTW, doesn't the backtrace posted in the original help?

[knz]

when you send SIGQUIT, this would produce a goroutine dump also in the log file. Can you check the last log file in the log directory?

[bra-fsn]

New entries from the log stop after the process starts eating CPU on two threads.
I've verified: if I send a SIGQUIT before I start the test load and it locks up, I get a goroutine dump.
After the lockup I get nothing.
The last lines are:

I200430 14:02:44.401158 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 460 goroutines, 69 MiB/28 MiB/132 MiB GO alloc/idle/total, 18 MiB/29 MiB CGO alloc/total, 6672.6 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (4x), 1.3 MiB/838 KiB (r/w)net
E200430 14:02:54.373573 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:02:54.373605 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:02:54.373646 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:02:54.417829 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 602 goroutines, 82 MiB/20 MiB/140 MiB GO alloc/idle/total, 40 MiB/58 MiB CGO alloc/total, 58324.4 CGO/sec, 0.0/0.0 %(u/s)time, 0.1 %gc (31x), 4.1 MiB/2.9 MiB (r/w)net
E200430 14:03:04.373451 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:03:04.373481 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:03:04.373522 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:03:04.424110 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 595 goroutines, 95 MiB/77 MiB/144 MiB GO alloc/idle/total, 72 MiB/90 MiB CGO alloc/total, 77701.2 CGO/sec, 0.0/0.0 %(u/s)time, 0.1 %gc (41x), 7.8 MiB/4.7 MiB (r/w)net
E200430 14:03:14.373422 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:03:14.373453 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:03:14.373493 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:03:14.418952 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 545 goroutines, 71 MiB/86 MiB/144 MiB GO alloc/idle/total, 45 MiB/64 MiB CGO alloc/total, 80930.6 CGO/sec, 0.0/0.0 %(u/s)time, 0.1 %gc (41x), 5.5 MiB/3.5 MiB (r/w)net
I200430 14:03:24.372556 165 gossip/gossip.go:567  [n1] gossip status (ok, 1 node)
gossip client (0/3 cur/max conns)
gossip server (0/3 cur/max conns, infos 0/0 sent/received, bytes 0B/0B sent/received)
gossip connectivity
  n1 [sentinel];
E200430 14:03:24.373729 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:03:24.373773 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:03:24.374094 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:03:24.433067 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 437 goroutines, 71 MiB/81 MiB/164 MiB GO alloc/idle/total, 23 MiB/41 MiB CGO alloc/total, 90972.1 CGO/sec, 0.0/0.0 %(u/s)time, 0.1 %gc (44x), 20 MiB/30 MiB (r/w)net
I200430 14:03:24.460624 228136 jobs/registry.go:797  [n1] job 551108622577041409: stepping through state running with error <nil>
I200430 14:03:24.501199 228136 jobs/registry.go:797  [n1] job 551108622577041409: stepping through state succeeded with error <nil>
I200430 14:03:24.508156 228136 jobs/registry.go:952  [n1] job 551108622577041409: status succeeded after adoption finished
I200430 14:03:24.558998 228662 jobs/registry.go:797  [n1] job 551108622782332929: stepping through state running with error <nil>
I200430 14:03:24.746730 228662 jobs/registry.go:797  [n1] job 551108622782332929: stepping through state succeeded with error <nil>
I200430 14:03:24.754428 228662 jobs/registry.go:952  [n1] job 551108622782332929: status succeeded after adoption finished
I200430 14:03:24.769632 230002 jobs/registry.go:797  [n1] job 551108623590785025: stepping through state running with error <nil>
I200430 14:03:24.895414 230002 jobs/registry.go:797  [n1] job 551108623590785025: stepping through state succeeded with error <nil>
I200430 14:03:24.902566 230002 jobs/registry.go:952  [n1] job 551108623590785025: status succeeded after adoption finished
I200430 14:03:24.931081 230366 jobs/registry.go:797  [n1] job 551108624090267649: stepping through state running with error <nil>
I200430 14:03:24.979513 230366 jobs/registry.go:797  [n1] job 551108624090267649: stepping through state succeeded with error <nil>
I200430 14:03:24.988134 230366 jobs/registry.go:952  [n1] job 551108624090267649: status succeeded after adoption finished
I200430 14:03:25.008578 231542 jobs/registry.go:797  [n1] job 551108624374267905: stepping through state running with error <nil>
I200430 14:03:25.039818 231542 jobs/registry.go:797  [n1] job 551108624374267905: stepping through state succeeded with error <nil>
I200430 14:03:25.051541 231542 jobs/registry.go:952  [n1] job 551108624374267905: status succeeded after adoption finished
I200430 14:03:25.091265 232192 jobs/registry.go:797  [n1] job 551108624588996609: stepping through state running with error <nil>
I200430 14:03:25.302839 232192 jobs/registry.go:797  [n1] job 551108624588996609: stepping through state succeeded with error <nil>
I200430 14:03:25.310664 232192 jobs/registry.go:952  [n1] job 551108624588996609: status succeeded after adoption finished
E200430 14:03:34.373484 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:03:34.373514 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:03:34.374129 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:03:34.420856 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 329 goroutines, 71 MiB/83 MiB/148 MiB GO alloc/idle/total, 42 MiB/63 MiB CGO alloc/total, 31607.5 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (14x), 4.4 MiB/2.4 MiB (r/w)net
E200430 14:03:44.373560 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:03:44.373591 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:03:44.373633 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:03:44.423248 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 375 goroutines, 66 MiB/85 MiB/150 MiB GO alloc/idle/total, 50 MiB/71 MiB CGO alloc/total, 15211.6 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (7x), 2.1 MiB/1.5 MiB (r/w)net
E200430 14:03:54.373563 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:03:54.373593 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:03:54.373634 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:03:54.431861 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 522 goroutines, 66 MiB/83 MiB/151 MiB GO alloc/idle/total, 66 MiB/87 MiB CGO alloc/total, 48458.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.1 %gc (24x), 4.1 MiB/3.3 MiB (r/w)net
E200430 14:04:04.373655 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:04:04.373686 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:04:04.373727 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:04:04.427292 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 437 goroutines, 88 MiB/77 MiB/149 MiB GO alloc/idle/total, 49 MiB/69 MiB CGO alloc/total, 74553.6 CGO/sec, 0.0/0.0 %(u/s)time, 0.1 %gc (37x), 9.0 MiB/5.8 MiB (r/w)net
E200430 14:04:14.373775 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:04:14.373807 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:04:14.373872 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:04:14.436700 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 498 goroutines, 92 MiB/78 MiB/152 MiB GO alloc/idle/total, 82 MiB/102 MiB CGO alloc/total, 74789.8 CGO/sec, 0.0/0.0 %(u/s)time, 0.1 %gc (38x), 5.7 MiB/3.8 MiB (r/w)net
I200430 14:04:24.372512 165 gossip/gossip.go:567  [n1] gossip status (ok, 1 node)
gossip client (0/3 cur/max conns)
gossip server (0/3 cur/max conns, infos 0/0 sent/received, bytes 0B/0B sent/received)
E200430 14:04:24.374140 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:04:24.374167 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:04:24.374394 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:04:24.417505 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 324 goroutines, 109 MiB/66 MiB/153 MiB GO alloc/idle/total, 43 MiB/64 MiB CGO alloc/total, 47061.5 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (22x), 3.8 MiB/2.8 MiB (r/w)net
I200430 14:04:25.329746 431262 jobs/registry.go:797  [n1] job 551108822033170433: stepping through state running with error <nil>
I200430 14:04:25.697888 431262 jobs/registry.go:797  [n1] job 551108822033170433: stepping through state succeeded with error <nil>
I200430 14:04:25.706174 431262 jobs/registry.go:952  [n1] job 551108822033170433: status succeeded after adoption finished
I200430 14:04:25.719954 431187 jobs/registry.go:797  [n1] job 551108823315841025: stepping through state running with error <nil>
I200430 14:04:25.968296 431187 jobs/registry.go:797  [n1] job 551108823315841025: stepping through state succeeded with error <nil>
I200430 14:04:25.975442 431187 jobs/registry.go:952  [n1] job 551108823315841025: status succeeded after adoption finished
I200430 14:04:25.989104 431422 jobs/registry.go:797  [n1] job 551108824199299073: stepping through state running with error <nil>
I200430 14:04:26.269484 431422 jobs/registry.go:797  [n1] job 551108824199299073: stepping through state succeeded with error <nil>
I200430 14:04:26.276545 431422 jobs/registry.go:952  [n1] job 551108824199299073: status succeeded after adoption finished
E200430 14:04:34.374071 170 server/status/runtime.go:408  [n1] unable to get mem usage: no such process
E200430 14:04:34.374108 170 server/status/runtime.go:412  [n1] unable to get cpu usage: no such process
E200430 14:04:34.374609 170 server/status/runtime.go:423  [n1] unable to get file descriptor usage: open /proc/49183/rlimit: no such file or directory
I200430 14:04:34.435949 170 server/status/runtime.go:498  [n1] runtime stats: 0 B RSS, 778 goroutines, 106 MiB/66 MiB/158 MiB GO alloc/idle/total, 64 MiB/90 MiB CGO alloc/total, 54958.8 CGO/sec, 0.0/0.0 %(u/s)time, 0.1 %gc (29x), 5.7 MiB/3.1 MiB (r/w)net

[knz]

I'm a bit stumped by the issue you're encountering.

• the goroutine you're catching in "yaccpar" is in a good place I think, that's a place we're expecting it to be while processing a query

• the other goroutine is busy doing garbage collection. It's possible—based on my vague understanding of the implementation—that it's spinning forever trying to stop the world (or restart it) after a GC pass.

I am very suspicious of this bug in the go runtime or maybe this one, both were fixed in 1.14.2. FWIW, we only support 1.13 to build cockroachdb 20.1 (although I personally use 1.14.2 and it seems fine).

Could you maybe retry building with go 1.14.2 and report your findings?

A side note (unrelated to your issue): you can make CockroachDB able to collect system stats and avoid the log spam by mounting /compat/linux/proc, e.g. by adding this to your /etc/fstab:

linproc                 /compat/linux/proc linprocfs rw         0       0

[bra-fsn]

Good catch! At least I could run the test load for 10 minutes, while before it died after 1 or 2. I'll let it run for a day, but I think you've found the root cause.
Because it happened after a given commit, I wasn't suspecting go. Maybe a new code stresses something which triggers this...

I'm running a native FreeBSD binary, so having linprocfs mounted on the /compat path won't help. CockroachDB tries to open files from /proc.
Mounting linprocfs there also has problems, because it tries to open /proc/74644/rlimit which doesn't exist.
The real solution would be to support FreeBSD in go sigar (cloudfoundry/gosigar#21), which I wanted to look at for a long time (haven't written a line of go code yet, so I'm not the most qualified to do that), but because I don't really care about those stats and CockroachDB works fine with this (currently, because there were some revisions which didn't), I haven't yet find the time for doing it...
But please don't break which works now. :)

[knz]

I wrote the freebsd support in gosigar. It's silly and requires both freebsd /proc and also Linux /compat/linux/proc to be mounted side by side. Obviously this should be better but I didn't have time to make it more elegant.

…

-- Verstuurd vanaf mijn Android apparaat met K-9 Mail. Excuseer mijn beknoptheid.

[knz]

That's also why I knew what you needed based on your logs. If you had been running a Linux binary I wouldn't have needed to tell you about proc because nearly all Linux programs need it.

[bra-fsn]

I wrote the freebsd support in gosigar. It's silly and requires both freebsd /proc and also Linux /compat/linux/proc to be mounted side by side. Obviously this should be better but I didn't have time to make it more elegant.

Oh, indeed! I didn't know that! I've tried to mount linprocfs a long time ago and after I saw it doesn't work, I saved that info and haven't tried to understand what happens.
I think in the last ~25 years I haven't had a machine which had /proc mounted, so this naturally didn't work.

Thanks a lot!

[bra-fsn]

It runs fine since then, so closing the issue. Thanks @knz!

[knz]

👍 Happy hacking