[Date Prev][Date Next]
Large delay before transmitting search result
- To: firstname.lastname@example.org
- Subject: Large delay before transmitting search result
- From: "Rene B. Elgaard" <email@example.com>
- Date: Mon, 12 Mar 2012 13:27:51 +0100
- Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20120113; h=message-id:date:from:user-agent:mime-version:to:subject :content-type:content-transfer-encoding; bh=X+cf4TrGi95nHNDrlyKZikxqN6B6IhPyLvTVAZGy4bc=; b=QvDMF/N55aCDmQO1F/70dej3MHovH6UrjqELEZ2LK1YIICacVSbW0e7UcGLYf099wd FrKFK4PQMVLZfLv1JvmYEgAbXzFs3AvG0RYQ6Hdf1W4c131Cli+5M8yYWVA6E9KvnbpO XRxtDPg6Hsm0+Q8QTnc+ONQTLUvpGa9KvFH1CEWK+gv1cc0hrSH2Tb9W3PX8zr1QgSRo UOsrzz/DCQIMojUKHdowspGAfrLtam/l/wjtZi374sRk+jLfS2mIF0yDStI0igzaxPyD UB/xAx9N1YADwE/Lz4Yw1M1dBjSXOMYUdc5l/FnwqgXTejxioOgofMsyR+0YBkvIV0lE snWg==
- User-agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:10.0.2) Gecko/20120216 Thunderbird/10.0.2
OpenLDAP 2.4.26 + BerkeleyDB 5.2.28, also seen on OpenLDAP 2.4.22 + BerkeleyDB 4.6.21
I am trying to investigate a response time issue.
Basically I am doing a search with ldapsearch that results in the transfer of an 8.5 Mb binary entry. This takes around 800 ms measured on the server itself from the request has been received until the response has been delivered..
Looking at what is going on on the network I see a large delay between slapd receiving the search request and the actual start of the transfer. This delay accounts for around 600ms.
So what is going on during this time ?
I am on Solaris 10, so I use dtrace to look at slapd, and it turns out that it calls memmove(<ADDR>,<ADDR> + 1, ~8.5 Mb).
That is it shifts the result 1 byte, and it does this 4 times. Each memmove takes around 150 ms, which accounts almost completely for the delay before doing the transfer over network.
I have written a small C program which does the same memmove and verified that on my setup, it does indeed take 150ms to shift 8.5 Mb 1 byte.
The stacktrace up until each memmove is
0 42451 memmove:entry *** Moving from 213650401 to 213650402 ***
The first line shows the source and destination address for memmove. The numbers themselves are not interesting, but the difference (1) is.
Why is it shifting the buffer 1 byte ?
If this could be optimized somehow, it could lead to a huge improvement in response time.