[Date Prev][Date Next] [Chronological] [Thread] [Top]
Re: (ITS#7566) ldapadd slower on Linux than BSD

To: openldap-its@OpenLDAP.org
Subject: Re: (ITS#7566) ldapadd slower on Linux than BSD
From: lm5@ualberta.ca
Date: Sat, 6 Apr 2013 19:08:25 GMT
Auto-submitted: auto-generated (OpenLDAP-ITS)
--bcaec54eef8cfe673204d9b5eb1e
Content-Type: text/plain; charset=ISO-8859-1

> So what is happening on the slapd server while things are paused?
>
> Also, if you use an ldapi:/// socket rather than a tcp/ip socket, do you
> see the same issue?
>

A have changed to use the ldapi:/// socket and there is no improvement.

It seems that one thread of slapd is repeatedly waiting on epoll_wait.
Strace prints
epoll_wait(6,
and then pauses for couple of seconds.

Iotop shows to slapd threads writing to disk. Right after I start ldapadd,
they write to disk at approximately 60MB/s each. Over time, they go down to
2-3 MB/s each.

TID    PRIO    USER    DISK READ    DISK WRITE    SWAPIN    IO    COMMAND
15264 be/4 ldap        0.00 B/s    2.81 M/s  0.00 % 99.99 % slapd -u ldap
-g ldap -f /etc/openldap/slapd.conf -h
ldapi://%2fvar%2frun%2fopenldap%2fslapd.sock
15255 be/4 ldap        0.00 B/s    3.00 M/s  0.00 % 19.48 % slapd -u ldap
-g ldap -f /etc/openldap/slapd.conf -h
ldapi://%2fvar%2frun%2fopenldap%2fslapd.sock

I took an strace for all the process and threads involved over a 2 minute
period.

Process slapd - main thread:
futex(0x7f2efa38e9d0, FUTEX_WAIT, 15251, NULL

Process slapd - thread:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 57.08    1.639877         474      3457       268 futex
 42.54    1.222208        1076      1136           fdatasync
  0.17    0.004913           0    272650           writev
  0.11    0.003194           3      1137           pwrite
  0.06    0.001736           0    272649           lseek
  0.02    0.000530           0      4544      1136 read
  0.01    0.000282           0      2273           write
  0.00    0.000132           0      2273           sendto
  0.00    0.000065           0      1136           open
  0.00    0.000061           0      1136           stat
  0.00    0.000041           0      1136           epoll_ctl
  0.00    0.000011           0      1136           close
  0.00    0.000000           0       116           mprotect
  0.00    0.000000           0      2272           fcntl
  0.00    0.000000           0      1136           getuid
  0.00    0.000000           0      1136           getppid
  0.00    0.000000           0      1136           gettid
------ ----------- ----------- --------- --------- ----------------
100.00    2.873050                570459      1404 total

Process slapd - thread:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 50.67    1.128008         399      2828       213 futex
 48.96    1.089974        1161       939           fdatasync
  0.15    0.003311           0    226607           writev
  0.13    0.002928           3       939           pwrite
  0.07    0.001544           0    226607           lseek
  0.01    0.000214           0      1879           write
  0.01    0.000139           0      1879           sendto
  0.00    0.000065           0       940           open
  0.00    0.000046           0      3760       940 read
  0.00    0.000029           0        94           mprotect
  0.00    0.000021           0       940           close
  0.00    0.000021           0       940           getppid
  0.00    0.000019           0       940           getuid
  0.00    0.000015           0       940           epoll_ctl
  0.00    0.000014           0       940           stat
  0.00    0.000000           0      1880           fcntl
  0.00    0.000000           0       940           gettid
------ ----------- ----------- --------- --------- ----------------
100.00    2.226348                473992      1153 total

Process slapd - thread:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0      1386           read
  -nan    0.000000           0     13861           sendto
  -nan    0.000000           0      3866       294 futex
  -nan    0.000000           0      2772           epoll_wait
  -nan    0.000000           0      1386           epoll_ctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                 23271       294 total

Process ldapadd:
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.19    0.056533          18      3194           poll
  0.48    0.000276           0      4866           read
  0.32    0.000183           0      6846           write
  0.00    0.000000           0         1           restart_syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.056992                 14907           total

--bcaec54eef8cfe673204d9b5eb1e
Content-Type: text/html; charset=ISO-8859-1
Content-Transfer-Encoding: base64

PGRpdiBkaXI9Imx0ciI+PGJyPjxkaXYgY2xhc3M9ImdtYWlsX2V4dHJhIj48ZGl2IGNsYXNzPSJn
bWFpbF9xdW90ZSI+PGJsb2NrcXVvdGUgY2xhc3M9ImdtYWlsX3F1b3RlIiBzdHlsZT0ibWFyZ2lu
OjBweCAwcHggMHB4IDAuOGV4O2JvcmRlci1sZWZ0OjFweCBzb2xpZCByZ2IoMjA0LDIwNCwyMDQp
O3BhZGRpbmctbGVmdDoxZXgiPjxkaXYgY2xhc3M9ImltIj48L2Rpdj48ZGl2IGNsYXNzPSJpbSI+
DQoNClNvIHdoYXQgaXMgaGFwcGVuaW5nIG9uIHRoZSBzbGFwZCBzZXJ2ZXIgd2hpbGUgdGhpbmdz
IGFyZSBwYXVzZWQ/PGJyPg0KPGJyPg0KQWxzbywgaWYgeW91IHVzZSBhbiBsZGFwaTovLy8gc29j
a2V0IHJhdGhlciB0aGFuIGEgdGNwL2lwIHNvY2tldCwgZG8geW91IHNlZSB0aGUgc2FtZSBpc3N1
ZT88YnI+PC9kaXY+PC9ibG9ja3F1b3RlPjxkaXY+oDxicj48L2Rpdj48ZGl2PkEgaGF2ZSBjaGFu
Z2VkIHRvIHVzZSB0aGUgbGRhcGk6Ly8vIHNvY2tldCBhbmQgdGhlcmUgaXMgbm8gaW1wcm92ZW1l
bnQuPGJyPjxicj48L2Rpdj4NCjxkaXY+SXQgc2VlbXMgdGhhdCBvbmUgdGhyZWFkIG9mIHNsYXBk
IGlzIHJlcGVhdGVkbHkgd2FpdGluZyBvbiBlcG9sbF93YWl0LiBTdHJhY2UgcHJpbnRzPGJyPmVw
b2xsX3dhaXQoNiw8YnI+PC9kaXY+PGRpdj5hbmQgdGhlbiBwYXVzZXMgZm9yIGNvdXBsZSBvZiBz
ZWNvbmRzLjxicj48L2Rpdj48ZGl2Pjxicj48L2Rpdj48ZGl2PklvdG9wIHNob3dzIHRvIHNsYXBk
IHRocmVhZHMgd3JpdGluZyB0byBkaXNrLiBSaWdodCBhZnRlciBJIHN0YXJ0IGxkYXBhZGQsIHRo
ZXkgd3JpdGUgdG8gZGlzayBhdCBhcHByb3hpbWF0ZWx5IDYwTUIvcyBlYWNoLiBPdmVyIHRpbWUs
IHRoZXkgZ28gZG93biB0byAyLTMgTUIvcyBlYWNoLjxicj4NCjxicj5USUSgoKAgUFJJT6CgoCBV
U0VSoKCgIERJU0sgUkVBRKCgoCBESVNLIFdSSVRFoKCgIFNXQVBJTqCgoCBJT6CgoCBDT01NQU5E
PGJyPjE1MjY0IGJlLzQgbGRhcKCgoKCgoKAgMC4wMCBCL3OgoKAgMi44MSBNL3OgIDAuMDAgJSA5
OS45OSAlIHNsYXBkIC11IGxkYXAgLWcgbGRhcCAtZiAvZXRjL29wZW5sZGFwL3NsYXBkLmNvbmYg
LWggbGRhcGk6Ly8lMmZ2YXIlMmZydW4lMmZvcGVubGRhcCUyZnNsYXBkLnNvY2s8YnI+DQoxNTI1
NSBiZS80IGxkYXCgoKCgoKCgIDAuMDAgQi9zoKCgIDMuMDAgTS9zoCAwLjAwICUgMTkuNDggJSBz
bGFwZCAtdSBsZGFwIC1nIGxkYXAgLWYgL2V0Yy9vcGVubGRhcC9zbGFwZC5jb25mIC1oIGxkYXBp
Oi8vJTJmdmFyJTJmcnVuJTJmb3BlbmxkYXAlMmZzbGFwZC5zb2NrPGJyPjxicj48L2Rpdj48ZGl2
PkkgdG9vayBhbiBzdHJhY2UgZm9yIGFsbCB0aGUgcHJvY2VzcyBhbmQgdGhyZWFkcyBpbnZvbHZl
ZCBvdmVyIGEgMiBtaW51dGUgcGVyaW9kLjxicj4NCjwvZGl2PjxkaXY+PGJyPjwvZGl2PjxkaXY+
UHJvY2VzcyBzbGFwZCAtIG1haW4gdGhyZWFkOjxicj5mdXRleCgweDdmMmVmYTM4ZTlkMCwgRlVU
RVhfV0FJVCwgMTUyNTEsIE5VTEw8YnI+PGJyPjwvZGl2PjxkaXY+UHJvY2VzcyBzbGFwZCAtIHRo
cmVhZDo8YnI+JSB0aW1loKCgoCBzZWNvbmRzoCB1c2Vjcy9jYWxsoKCgoCBjYWxsc6CgoCBlcnJv
cnMgc3lzY2FsbDxicj4tLS0tLS0gLS0tLS0tLS0tLS0gLS0tLS0tLS0tLS0gLS0tLS0tLS0tIC0t
LS0tLS0tLSAtLS0tLS0tLS0tLS0tLS0tPGJyPg0KoDU3LjA4oKCgIDEuNjM5ODc3oKCgoKCgoKAg
NDc0oKCgoKAgMzQ1N6CgoKCgoCAyNjggZnV0ZXg8YnI+oDQyLjU0oKCgIDEuMjIyMjA4oKCgoKCg
oCAxMDc2oKCgoKAgMTEzNqCgoKCgoKCgoKAgZmRhdGFzeW5jPGJyPqAgMC4xN6CgoCAwLjAwNDkx
M6CgoKCgoKCgoKAgMKCgoCAyNzI2NTCgoKCgoKCgoKCgIHdyaXRldjxicj6gIDAuMTGgoKAgMC4w
MDMxOTSgoKCgoKCgoKCgIDOgoKCgoCAxMTM3oKCgoKCgoKCgoCBwd3JpdGU8YnI+DQqgIDAuMDag
oKAgMC4wMDE3MzagoKCgoKCgoKCgIDCgoKAgMjcyNjQ5oKCgoKCgoKCgoCBsc2Vlazxicj6gIDAu
MDKgoKAgMC4wMDA1MzCgoKCgoKCgoKCgIDCgoKCgoCA0NTQ0oKCgoKAgMTEzNiByZWFkPGJyPqAg
MC4wMaCgoCAwLjAwMDI4MqCgoKCgoKCgoKAgMKCgoKCgIDIyNzOgoKCgoKCgoKCgIHdyaXRlPGJy
PqAgMC4wMKCgoCAwLjAwMDEzMqCgoKCgoKCgoKAgMKCgoKCgIDIyNzOgoKCgoKCgoKCgIHNlbmR0
bzxicj4NCqAgMC4wMKCgoCAwLjAwMDA2NaCgoKCgoKCgoKAgMKCgoKCgIDExMzagoKCgoKCgoKCg
IG9wZW48YnI+oCAwLjAwoKCgIDAuMDAwMDYxoKCgoKCgoKCgoCAwoKCgoKAgMTEzNqCgoKCgoKCg
oKAgc3RhdDxicj6gIDAuMDCgoKAgMC4wMDAwNDGgoKCgoKCgoKCgIDCgoKCgoCAxMTM2oKCgoKCg
oKCgoCBlcG9sbF9jdGw8YnI+oCAwLjAwoKCgIDAuMDAwMDExoKCgoKCgoKCgoCAwoKCgoKAgMTEz
NqCgoKCgoKCgoKAgY2xvc2U8YnI+DQqgIDAuMDCgoKAgMC4wMDAwMDCgoKCgoKCgoKCgIDCgoKCg
oKAgMTE2oKCgoKCgoKCgoCBtcHJvdGVjdDxicj6gIDAuMDCgoKAgMC4wMDAwMDCgoKCgoKCgoKCg
IDCgoKCgoCAyMjcyoKCgoKCgoKCgoCBmY250bDxicj6gIDAuMDCgoKAgMC4wMDAwMDCgoKCgoKCg
oKCgIDCgoKCgoCAxMTM2oKCgoKCgoKCgoCBnZXR1aWQ8YnI+oCAwLjAwoKCgIDAuMDAwMDAwoKCg
oKCgoKCgoCAwoKCgoKAgMTEzNqCgoKCgoKCgoKAgZ2V0cHBpZDxicj4NCqAgMC4wMKCgoCAwLjAw
MDAwMKCgoKCgoKCgoKAgMKCgoKCgIDExMzagoKCgoKCgoKCgIGdldHRpZDxicj4tLS0tLS0gLS0t
LS0tLS0tLS0gLS0tLS0tLS0tLS0gLS0tLS0tLS0tIC0tLS0tLS0tLSAtLS0tLS0tLS0tLS0tLS0t
PGJyPjEwMC4wMKCgoCAyLjg3MzA1MKCgoKCgoKCgoKCgoKCgoCA1NzA0NTmgoKCgoCAxNDA0IHRv
dGFsPGJyPjxicj5Qcm9jZXNzIHNsYXBkIC0gdGhyZWFkOjxicj4NCiUgdGltZaCgoKAgc2Vjb25k
c6AgdXNlY3MvY2FsbKCgoKAgY2FsbHOgoKAgZXJyb3JzIHN5c2NhbGw8YnI+LS0tLS0tIC0tLS0t
LS0tLS0tIC0tLS0tLS0tLS0tIC0tLS0tLS0tLSAtLS0tLS0tLS0gLS0tLS0tLS0tLS0tLS0tLTxi
cj6gNTAuNjegoKAgMS4xMjgwMDigoKCgoKCgoCAzOTmgoKCgoCAyODI4oKCgoKCgIDIxMyBmdXRl
eDxicj6gNDguOTagoKAgMS4wODk5NzSgoKCgoKCgIDExNjGgoKCgoKAgOTM5oKCgoKCgoKCgoCBm
ZGF0YXN5bmM8YnI+DQqgIDAuMTWgoKAgMC4wMDMzMTGgoKCgoKCgoKCgIDCgoKAgMjI2NjA3oKCg
oKCgoKCgoCB3cml0ZXY8YnI+oCAwLjEzoKCgIDAuMDAyOTI4oKCgoKCgoKCgoCAzoKCgoKCgIDkz
OaCgoKCgoKCgoKAgcHdyaXRlPGJyPqAgMC4wN6CgoCAwLjAwMTU0NKCgoKCgoKCgoKAgMKCgoCAy
MjY2MDegoKCgoKCgoKCgIGxzZWVrPGJyPqAgMC4wMaCgoCAwLjAwMDIxNKCgoKCgoKCgoKAgMKCg
oKCgIDE4NzmgoKCgoKCgoKCgIHdyaXRlPGJyPg0KoCAwLjAxoKCgIDAuMDAwMTM5oKCgoKCgoKCg
oCAwoKCgoKAgMTg3OaCgoKCgoKCgoKAgc2VuZHRvPGJyPqAgMC4wMKCgoCAwLjAwMDA2NaCgoKCg
oKCgoKAgMKCgoKCgoCA5NDCgoKCgoKCgoKCgIG9wZW48YnI+oCAwLjAwoKCgIDAuMDAwMDQ2oKCg
oKCgoKCgoCAwoKCgoKAgMzc2MKCgoKCgoCA5NDAgcmVhZDxicj6gIDAuMDCgoKAgMC4wMDAwMjmg
oKCgoKCgoKCgIDCgoKCgoKCgIDk0oKCgoKCgoKCgoCBtcHJvdGVjdDxicj4NCqAgMC4wMKCgoCAw
LjAwMDAyMaCgoKCgoKCgoKAgMKCgoKCgoCA5NDCgoKCgoKCgoKCgIGNsb3NlPGJyPqAgMC4wMKCg
oCAwLjAwMDAyMaCgoKCgoKCgoKAgMKCgoKCgoCA5NDCgoKCgoKCgoKCgIGdldHBwaWQ8YnI+oCAw
LjAwoKCgIDAuMDAwMDE5oKCgoKCgoKCgoCAwoKCgoKCgIDk0MKCgoKCgoKCgoKAgZ2V0dWlkPGJy
PqAgMC4wMKCgoCAwLjAwMDAxNaCgoKCgoKCgoKAgMKCgoKCgoCA5NDCgoKCgoKCgoKCgIGVwb2xs
X2N0bDxicj4NCqAgMC4wMKCgoCAwLjAwMDAxNKCgoKCgoKCgoKAgMKCgoKCgoCA5NDCgoKCgoKCg
oKCgIHN0YXQ8YnI+oCAwLjAwoKCgIDAuMDAwMDAwoKCgoKCgoKCgoCAwoKCgoKAgMTg4MKCgoKCg
oKCgoKAgZmNudGw8YnI+oCAwLjAwoKCgIDAuMDAwMDAwoKCgoKCgoKCgoCAwoKCgoKCgIDk0MKCg
oKCgoKCgoKAgZ2V0dGlkPGJyPi0tLS0tLSAtLS0tLS0tLS0tLSAtLS0tLS0tLS0tLSAtLS0tLS0t
LS0gLS0tLS0tLS0tIC0tLS0tLS0tLS0tLS0tLS08YnI+DQoxMDAuMDCgoKAgMi4yMjYzNDigoKCg
oKCgoKCgoKCgoKAgNDczOTkyoKCgoKAgMTE1MyB0b3RhbDxicj48YnI+PC9kaXY+PGRpdj5Qcm9j
ZXNzIHNsYXBkIC0gdGhyZWFkOjxicj4lIHRpbWWgoKCgIHNlY29uZHOgIHVzZWNzL2NhbGygoKCg
IGNhbGxzoKCgIGVycm9ycyBzeXNjYWxsPGJyPi0tLS0tLSAtLS0tLS0tLS0tLSAtLS0tLS0tLS0t
LSAtLS0tLS0tLS0gLS0tLS0tLS0tIC0tLS0tLS0tLS0tLS0tLS08YnI+DQqgIC1uYW6goKAgMC4w
MDAwMDCgoKCgoKCgoKCgIDCgoKCgoCAxMzg2oKCgoKCgoKCgoCByZWFkPGJyPqAgLW5hbqCgoCAw
LjAwMDAwMKCgoKCgoKCgoKAgMKCgoKAgMTM4NjGgoKCgoKCgoKCgIHNlbmR0bzxicj6gIC1uYW6g
oKAgMC4wMDAwMDCgoKCgoKCgoKCgIDCgoKCgoCAzODY2oKCgoKCgIDI5NCBmdXRleDxicj6gIC1u
YW6goKAgMC4wMDAwMDCgoKCgoKCgoKCgIDCgoKCgoCAyNzcyoKCgoKCgoKCgoCBlcG9sbF93YWl0
PGJyPg0KoCAtbmFuoKCgIDAuMDAwMDAwoKCgoKCgoKCgoCAwoKCgoKAgMTM4NqCgoKCgoKCgoKAg
ZXBvbGxfY3RsPGJyPi0tLS0tLSAtLS0tLS0tLS0tLSAtLS0tLS0tLS0tLSAtLS0tLS0tLS0gLS0t
LS0tLS0tIC0tLS0tLS0tLS0tLS0tLS08YnI+MTAwLjAwoKCgIDAuMDAwMDAwoKCgoKCgoKCgoKCg
oKCgoCAyMzI3MaCgoKCgoCAyOTQgdG90YWw8YnI+PGJyPlByb2Nlc3MgbGRhcGFkZDo8YnI+JSB0
aW1loKCgoCBzZWNvbmRzoCB1c2Vjcy9jYWxsoKCgoCBjYWxsc6CgoCBlcnJvcnMgc3lzY2FsbDxi
cj4NCi0tLS0tLSAtLS0tLS0tLS0tLSAtLS0tLS0tLS0tLSAtLS0tLS0tLS0gLS0tLS0tLS0tIC0t
LS0tLS0tLS0tLS0tLS08YnI+oDk5LjE5oKCgIDAuMDU2NTMzoKCgoKCgoKCgIDE4oKCgoKAgMzE5
NKCgoKCgoKCgoKAgcG9sbDxicj6gIDAuNDigoKAgMC4wMDAyNzagoKCgoKCgoKCgIDCgoKCgoCA0
ODY2oKCgoKCgoKCgoCByZWFkPGJyPqAgMC4zMqCgoCAwLjAwMDE4M6CgoKCgoKCgoKAgMKCgoKCg
IDY4NDagoKCgoKCgoKCgIHdyaXRlPGJyPg0KoCAwLjAwoKCgIDAuMDAwMDAwoKCgoKCgoKCgoCAw
oKCgoKCgoKAgMaCgoKCgoKCgoKAgcmVzdGFydF9zeXNjYWxsPGJyPi0tLS0tLSAtLS0tLS0tLS0t
LSAtLS0tLS0tLS0tLSAtLS0tLS0tLS0gLS0tLS0tLS0tIC0tLS0tLS0tLS0tLS0tLS08YnI+MTAw
LjAwoKCgIDAuMDU2OTkyoKCgoKCgoKCgoKCgoKCgoCAxNDkwN6CgoKCgoKCgoKAgdG90YWw8YnI+
PC9kaXY+PC9kaXY+PC9kaXY+PC9kaXY+DQo=
--bcaec54eef8cfe673204d9b5eb1e--
Prev by Date: Re: (ITS#7566) ldapadd slower on Linux than BSD
Next by Date: (ITS#7567) Alias dereferencing slowness
Index(es):
- Chronological
- Thread