CentOS

What cpimport mode is this happening ?

Hi,

I'am the customer who reported this issue, cpimport is used in default mode :

mode 1 - rows will be loaded in a distributed manner across PMs.

2016-10-07 22:11:14 (87677) INFO : Running distributed import (mode 1) on all PMs...

2016-10-07 22:11:16 (87677) INFO : For table modulo_0005.p1029: 105 rows processed and 1 rows inserted.

2016-10-07 22:11:16 (87677) INFO : Bulk load completed, total run time : 2.25727 seconds

So 1 ligne I have to wait near 20 secondes, as you can see : (I cut useless)

Can someone please provide the full debug log at the time this occurs so we can look into a way of reproducing it?

Reproduced the problem. Attached a PMP output during the delay. Appears to be the message queue waiting for data and timing out.

Runtime data:

2017-01-16 22:12:54 (27859) INFO : Running distributed import (mode 1) on all PMs...

2017-01-16 22:13:28 (27859) INFO : For table test.numbers: 100000000 rows processed and 100000000 rows inserted.

2017-01-16 22:13:28 (27859) INFO : Bulk load completed, total run time : 34.6954 seconds

real	0m58.931s

user	0m7.145s

sys	0m1.320s

At the end of a cpimport there is a read timeout added which is 1 sec * PM count on each connection. There is then a race where we could (very likely) enter a socket poll with that timeout before we check to see if the connection has actually ended.

This accumulates at the end of the run due to the serial thread joining which again is a race between thread joining and polling. Maximum delay would be in the region of 'number of PMs' squared.

There is no obvious reason for the delay to be there since the loop will re-enter the recv() on the default 20ms so the extra timeout only appears to save a little CPU time on the loops at the end. This fix removes the extra timeout.

This has been tested with a full speed VirtualBox network and an artificial 500ms delay added using 'tc qdisc add dev enp0s3 root netem delay 500ms' to make sure there are no obvious side-effects.

A one time test with multiple PMs to see if the delay is gone should suffice. Regression test should catch the unlikely scenario that a problem was introduced.

Build tested: Github source

[root@localhost columnstore]# cd mariadb-columnstore-server/
[root@localhost mariadb-columnstore-server]# git show
commit 3da188e5c8a2630019ea810fb8c1bd3ece5e058b
Merge: 5d9686c 53c1df7
Author: Andrew Hutchings <andrew@linuxjedi.co.uk>
Date: Fri Feb 10 15:07:31 2017 +0000

Merge pull request #31 from jbfavre/fix_deb_package_dependency

MCOL-562 Fix Debian package dependencies

[root@localhost mariadb-columnstore-server]# cd mariadb-columnstore-engine/
[root@localhost mariadb-columnstore-engine]# git show
commit 16cef50caedd9ec7585b04c096996a9441bdf2d5
Author: David Hill <david.hill@mariadb.com>
Date: Wed Mar 1 10:39:11 2017 -0600

change the check for prompt back to the previous code

Verified on a 1UM4PM stack.

[root@localhost ~]# date /usr/local/mariadb/columnstore/bin/cpimport
cpimport cpimport.bin
[root@localhost ~]# date /usr/local/mariadb/columnstore/bin/cpimport mytest lineitem /data/qa/source/dbt3/1g/lineitem.tbl
date: extra operand ‘mytest’
Try 'date --help' for more information.
[root@localhost ~]# time /usr/local/mariadb/columnstore/bin/cpimport mytest lineitem /data/qa/source/dbt3/1g/lineitem.tbl
2017-03-01 22:34:31 (11804) INFO : Running distributed import (mode 1) on all PMs...
2017-03-01 22:34:43 (11804) INFO : For table mytest.lineitem: 6001215 rows processed and 6001215 rows inserted.
2017-03-01 22:34:43 (11804) INFO : Bulk load completed, total run time : 12.2397 seconds

real 0m12.622s
user 0m1.220s
sys 0m1.612s
You have mail in /var/spool/mail/root