Date: 2016-07-25 16:29:50 +0200
From: anthonin.bonnefoy
To: SQL devs <>
Version: 11.21.11 (Jul2015-SP1)
CC: @njnes

Last updated: 2017-01-26 14:56:47 +0100

Comment 22251

Date: 2016-07-25 16:29:50 +0200
From: anthonin.bonnefoy

User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:45.0) Gecko/20100101 Firefox/45.0
Build Identifier:

After a lot of drop occurred on a database, mserver5 can take more than 1 hour to start.

Reproducible: Always

Steps to Reproduce:

1. Fill a database with given script, relaunch it for slower time

!/bin/bash
set -e

tables=$(echo "\d test_*" | mclient -i nova | cut -f3 -d" ")
for table in $tables; do
mclient nova -s "drop table $table;" > /dev/null
done

drop_query=""
create_query=""
NUM_OP=100000
SECONDS=0
for (( i = 0; i < NUM_OP; i++ )); do
num=$((i % 400))
table="test_$num"
create_query="$create_query CREATE TABLE $table (poller TEXT);"
drop_query="$drop_query; drop table $table;"

 if [[ $((i % 100)) == 0 ]]; then
     mclient nova -s "$create_query" > /dev/null
     create_query=""
 fi
 if [[ $((i % 400)) == 0 ]]; then
     mclient nova -s "$drop_query" > /dev/null
     drop_query=""
 fi
 if [[ $((i % 10000)) == 0 ]]; then
     echo "At $i/$NUM_OP, took $SECONDS seconds"
     SECONDS=0
 fi

done
mclient nova -s "$create_query" > /dev/null
mclient nova -s "$drop_query" > /dev/null

create_query=""
for (( i = 0; i < 100000; i++ )); do
table="test_$i"
create_query="$create_query CREATE TABLE $table (poller TEXT);"
if [[ $((i % 100)) == 0 ]]; then
mclient nova -s "$create_query" > /dev/null
create_query=""
fi
done

2. Check necessary time used to start mserver5 with

pkill mserver5; while pgrep mserver5; do sleep 1; done; time mclient nova -s ""

Here is the stacktrace on startup.

0 0x00007f9c6092f32d in BAThash (b=0x3a01df0, masksize=0) at gdk_search.c:488
1 0x00007f9c60a60dd0 in BUNfnd (b=0x3a01df0, v=0x7ffd75ae4738) at gdk_bat.c:1893
2 0x00007f9c59ca7155 in column_lookup_row (tr=0x27da1c0, c=0x3a7da6e0, value=0x7ffd75ae48fc) at bat_table.c:164
3 0x00007f9c59ca73bb in column_find_row (tr=0x27da1c0, c=0x3a7da6e0, value=0x7ffd75ae48fc) at bat_table.c:186
4 0x00007f9c59c925b2 in load_table (tr=0x27da1c0, s=0x3a7d6d30, tid=5689, nrs=0x9246010) at store.c:598
5 0x00007f9c59c94732 in load_schema (tr=0x27da1c0, id=2155, rid=9223372036854775808) at store.c:920
6 0x00007f9c59c94db4 in load_trans (tr=0x27da1c0, id=2155) at store.c:993
7 0x00007f9c59c976df in store_init (debug=0, store=store_bat, readonly=0, singleuser=0, logdir=0x7f9c59cd7820 "sql_logs", stk=0) at store.c:1558
8 0x00007f9c59c0f056 in mvc_init (debug=0, store=store_bat, ro=0, su=0, stk=0) at sql_mvc.c:36
9 0x00007f9c59b72d56 in SQLinit () at sql_scenario.c:251
10 0x00007f9c59b72a50 in SQLprelude (ret=0x7e60220) at sql_scenario.c:178
11 0x00007f9c60fd8f69 in malCommandCall (stk=0x7e60010, pci=0x9200270) at mal_interpreter.c:77
12 0x00007f9c60fdb830 in runMALsequence (cntxt=0x79d0010, mb=0x7b88010, startpc=1, stoppc=0, stk=0x7e60010, env=0x0, pcicaller=0x0) at mal_interpreter.c:655
13 0x00007f9c60fda91c in runMAL (cntxt=0x79d0010, mb=0x7b88010, mbcaller=0x0, env=0x0) at mal_interpreter.c:365
14 0x00007f9c60ffe480 in MALengine (c=0x79d0010) at mal_session.c:637
15 0x00007f9c60ffc8c8 in malBootstrap () at mal_session.c:57
16 0x00007f9c60fbbf09 in mal_init () at mal.c:95
17 0x0000000000403a49 in main (argc=20, av=0x7ffd75ae5dd8) at mserver5.c:650

For each non deleted tables (store.c:920), it searches the rid in _tables.id.
While looking up the row in _tables.id, BUNfnd is called on deleted elements of _tables.id.
Since hash is not present, it is computed and destroyed at bat_destroy (bat_table.c:171)

So, at startup, it computes the hash on deleted _tables.id on each table.
On my test database, it took more than 10 minutes with 100K tables and 700K deleted tables.

The same problem happen for function drop: Given the script

!/bin/bash
set -e

SECONDS=0
NUM_OP=500000

drop_query=""
create_query=""
for (( i = 0; i < NUM_OP; i++ )); do
fun="toto_$((i % 400))"
create_query="$create_query create function $fun(value bigint) returns hugeint begin return 0; end;;"
drop_query="$drop_query DROP function $fun;"

 if [[ $((i % 100)) == 0 ]]; then
     mclient nova -s "$create_query" > /dev/null
     mclient nova -s "$drop_query" > /dev/null
     create_query=""
     drop_query=""
 fi

 if [[ $((i % 10000)) == 0 ]]; then
     echo "At $i/$NUM_OP, took $SECONDS seconds"
     SECONDS=0
 fi

done

The drop take more and more times with most times spend in

0 0x00007f8aafc717b4 in BATins_kdiff (bn=0x445dc10, l=0x44f21d0, r=0x445da50) at gdk_setop.c:428
1 0x00007f8aafc877e6 in diff_intersect (l=0x44f21d0, r=0x445da50, diff=1) at gdk_setop.c:473
2 0x00007f8aafc87d03 in BATkdiff (l=0x44f21d0, r=0x445da50) at gdk_setop.c:514
3 0x00007f8aa8f798a6 in _delta_cands (tr=0x248efd0, t=0x43d1cd0) at bat_table.c:37
4 0x00007f8aa8f799e4 in delta_cands (tr=0x248efd0, t=0x43d1cd0) at bat_table.c:62
5 0x00007f8aa8f7ae00 in rids_select (tr=0x248efd0, key=0x43d1f30, key_value_low=0xe964b64, key_value_high=0xe964b64) at bat_table.c:347
6 0x00007f8aa8f72998 in sys_drop_func (tr=0x248efd0, func=0xe964b50, drop_action=1) at store.c:3802
7 0x00007f8aa8f73727 in sql_trans_drop_func (tr=0x248efd0, s=0x43d0010, id=416883, drop_action=0) at store.c:3994
8 0x00007f8aa8ee48e0 in mvc_drop_func (m=0x4488410, s=0x43d0010, f=0xe964b50, drop_action=0) at sql_mvc.c:830
9 0x00007f8aa8e2d3f8 in drop_func (sql=0x4488410, sname=0x3f4ceb0 "sys", name=0x4490a60 "toto_131", fid=416883, type=1, action=0) at sql.c:808
10 0x00007f8aa8e2fc75 in SQLcatalog (cntxt=0x2678320, mb=0x3f31ff0, stk=0x4443610, pci=0x3efe4d0) at sql.c:1340
11 0x00007f8ab02ae80b in runMALsequence (cntxt=0x2678320, mb=0x3f31ff0, startpc=1, stoppc=0, stk=0x4443610, env=0x0, pcicaller=0x0) at mal_interpreter.c:631
12 0x00007f8ab02adcab in callMAL (cntxt=0x2678320, mb=0x3f31ff0, env=0x7f8aa7fd1aa8, argv=0x7f8aa7fd1b00, debug=0 '\000') at mal_interpreter.c:447
13 0x00007f8aa8e4a91e in SQLexecutePrepared (c=0x2678320, be=0x41f9f50, q=0x3f2f410) at sql_execute.c:328
14 0x00007f8aa8e4ad74 in SQLengineIntern (c=0x2678320, be=0x41f9f50) at sql_execute.c:390
15 0x00007f8aa8e49916 in SQLengine (c=0x2678320) at sql_scenario.c:1323
16 0x00007f8ab02cf3d6 in runPhase (c=0x2678320, phase=4) at mal_scenario.c:515
17 0x00007f8ab02cf5b4 in runScenarioBody (c=0x2678320) at mal_scenario.c:559
18 0x00007f8ab02cf6c4 in runScenario (c=0x2678320) at mal_scenario.c:579
19 0x00007f8ab02d079a in MSserveClient (dummy=0x2678320) at mal_session.c:439
20 0x00007f8ab02d0309 in MSscheduleClient (command=0x4488410 "", challenge=0x7f8aa7fd1e30 "qkFs6TfH", fin=0x44935d0, fout=0x2491ba0) at mal_session.c:319
21 0x00007f8ab038df72 in doChallenge (data=0x44935e0) at mal_mapi.c:184
22 0x00007f8aafd45ea5 in thread_starter (arg=0x44934e0) at gdk_system.c:459
23 0x00007f8aae8340a4 in start_thread (arg=0x7f8aa7fd2700) at pthread_create.c:309
24 0x00007f8aae56987d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Comment 22310

Date: 2016-08-19 16:59:00 +0200
From: @njnes

this should be solved on the Jun2016 release.

Comment 24765

Date: 2016-12-08 14:59:23 +0100
From: anthonin.bonnefoy

Same problem with June2016 (it's segfaulting on the current rel-Dec2016)

I changed the script to try to trigger the problem more easily.
The main changes is to create table with more columns, you can remove the perf record if you're not interested in it.

!/bin/bash
set -eu

FARM="/tmp/farm"

init_farm() {
pkill -e -9 mserver5 || true
pkill -e -9 monetdbd || true
while pgrep -f monetdbd; do
sleep 1
done

 sudo umount "$FARM" || true
 rm -rf "$FARM"
 mkdir -p "$FARM"

 sudo mount -t tmpfs -o size=6G tmpfs "$FARM"

 monetdbd create "$FARM"
 monetdbd start "$FARM"

 while ! pgrep -f monetdbd; do
     sleep 1
 done

 monetdb create nova
 monetdb release nova

 perf record -g mserver5 --dbpath="$FARM/nova" \
     --set merovingian_uri=mapi:monetdb://octonion:50000/nova \
     --set mapi_open=false --set mapi_port=0 \
     --set mapi_usock="$FARM/nova/.mapi.sock" \
     --set monet_vault_key="$FARM/nova/.vaultkey" \
     --set gdk_nr_threads=4 --set max_clients=64 \
     --set sql_optimizer=default_pipe --set monet_daemon=yes &
 mserver5_pid=$!
 sleep 1

}

init_farm

drop_query=""
create_query=""

NUM_OP=20000
DROP_FREQUENCY=5000
SECONDS=0
for (( i = 0; i <= NUM_OP; i++ )); do
num=$((i % DROP_FREQUENCY))
table="test_$num"
create_query="$create_query CREATE TABLE $table (a1 INT, a2 INT, a3 INT,
a4 INT, a5 INT, a6 INT, a7 INT, a8 INT, a9 INT, a10 INT, a11 INT,
a12 INT, a13 INT, a14 INT, a15 INT, a16 INT, a17 INT, a18 INT, a19 INT,
a20 INT, a21 INT, a22 INT, a23 INT, a24 INT, a25 INT, a26 INT, a27 INT,
a28 INT, a29 INT, a30 INT, a31 INT, a32 INT, a33 INT, a34 INT, a35 INT,
a36 INT, a37 INT, a38 INT, a39 INT, a40 INT, a41 INT, a42 INT, a43 INT,
a44 INT, a45 INT, a46 INT, a47 INT, a48 INT, a49 INT, a50 INT, a51 INT,
a52 INT, a53 INT, a54 INT, a55 INT, a56 INT, a57 INT, a58 INT, a59 INT,
a60 INT, a61 INT, a62 INT, a63 INT, a64 INT, a65 INT, a66 INT, a67 INT,
a68 INT, a69 INT, a70 INT, a71 INT, a72 INT, a73 INT, a74 INT, a75 INT);"
drop_query="$drop_query; drop table $table;"

 if [[ $((i % 100)) == 0 ]]; then
     mclient nova -s "$create_query" > /dev/null
     create_query=""
 fi
 if [[ $((i % DROP_FREQUENCY)) == 0 ]]; then
     echo "Creations at $i/$NUM_OP, took $SECONDS seconds, starting drop"
             SECONDS=0

     mclient nova -s "$drop_query" > /dev/null
     drop_query=""

     echo "Drop at $i/$NUM_OP, took $SECONDS seconds"
             SECONDS=0
 fi

done

kill "$mserver5_pid"

Creations at 0/20000, took 0 seconds, starting drop
Drop at 0/20000, took 0 seconds
Creations at 5000/20000, took 23 seconds, starting drop
Drop at 5000/20000, took 18 seconds
Creations at 10000/20000, took 19 seconds, starting drop
Drop at 10000/20000, took 39 seconds
Creations at 15000/20000, took 19 seconds, starting drop
Drop at 15000/20000, took 47 seconds
Creations at 20000/20000, took 19 seconds, starting drop
^C[ perf record: Woken up 8039 times to write data ]

I had to interrupt it since it was taking more than 30 minutes on the last batch of drop.

The perf report -i perf.data --no-children gives

• 58.63% mserver5 libbat.so.13.0.6 [.] BAThash
  as the function using the most samples.

Thoses samples are taken without io overhead since we are on a tmpfs.

Comment 24812

Date: 2016-12-18 21:05:52 +0100
From: @njnes

the slow startup because of the drop tables has been fixed in the Dec2016 version. A vacuum solution for system tables is pending.

Comment 24920

Date: 2017-01-26 14:56:47 +0100
From: @kutsurak

Fixed in version Dec2016-SP1.