slapo-accesslog: wrong timestamp microseconds

To: openldap-technical@openldap.org

Subject: slapo-accesslog: wrong timestamp microseconds

From: Dario Zanzico <dario@dariozanzico.com>

Date: Thu, 18 Feb 2016 11:04:54 +0100

Dkim-signature: v=1; a=rsa-sha1; c=relaxed/relaxed; d= messagingengine.com; h=content-transfer-encoding:content-type :date:from:message-id:mime-version:subject:to:x-sasl-enc :x-sasl-enc; s=smtpout; bh=hGZTSJrFSCjQFBtPgalVRnrf3ZQ=; b=RUtc9 +p9kXUexr/gdQ16bUaJhaT2PzysK2I+I5/1wIpFT4k64OJtV6H8RMNm6jWZqprAw gDwc5THwHoCj1yIAp85lRj3vpFKPcWoVVMzM17Qfs64UftCgSypdOmYdlUwjGhGJ SukjlnH4AePi+aPud5BbU37+li8bHEyO5Ij0ZM=

In adding an accesslog overlay I noticed something strange with the reqstart and reqend fields:

the fractional part always begins with 000 and has this strange distribution.

$ ldapsearch ..... | awk -F . '/^reqStart: / {print $2}'| sort | uniq -c

2 000000Z

351 000001Z

73 000002Z

70 000003Z

308 000004Z

81 000005Z

97 000006Z

312 000007Z

97 000008Z

97 000009Z

297 000010Z

105 000011Z

92 000012Z

294 000013Z

108 000014Z

95 000015Z

271 000016Z

128 000017Z

97 000018Z

252 000019Z

126 000020Z

113 000021Z

240 000022Z

132 000023Z

110 000024Z

230 000025Z

155 000026Z

118 000027Z

209 000028Z

150 000029Z

111 000030Z

193 000031Z

161 000032Z

103 000033Z

187 000034Z

152 000035Z

117 000036Z

174 000037Z

145 000038Z

117 000039Z

140 000040Z

126 000041Z

94 000042Z

89 000043Z

98 000044Z

72 000045Z

51 000046Z

49 000047Z

27 000048Z

27 000049Z

26 000050Z

12 000051Z

13 000052Z

12 000053Z

9 000054Z

7 000055Z

6 000056Z

8 000057Z

10 000058Z

5 000059Z

3 000060Z

3 000061Z

5 000062Z

3 000063Z

7 000064Z

3 000065Z

7 000066Z

8 000067Z

1 000068Z

6 000069Z

5 000070Z

5 000071Z

4 000072Z

8 000073Z

2 000074Z

3 000075Z

11 000076Z

1 000077Z

4 000078Z

7 000079Z

6 000080Z

5 000081Z

6 000082Z

5 000083Z

2 000084Z

8 000085Z

3 000086Z

1 000087Z

9 000088Z

3 000089Z

3 000090Z

6 000091Z

3 000092Z

6 000093Z

5 000094Z

4 000095Z

4 000096Z

3 000097Z

4 000098Z

3 000099Z

4 000100Z

3 000101Z

6 000102Z

8 000103Z

1 000104Z

3 000105Z

4 000106Z

5 000107Z

2 000108Z

4 000109Z

4 000111Z

10 000112Z

5 000113Z

2 000114Z

3 000115Z

2 000116Z

4 000117Z

3 000118Z

4 000119Z

1 000120Z

4 000121Z

2 000122Z

4 000123Z

8 000124Z

3 000125Z

4 000126Z

4 000127Z

2 000128Z

3 000129Z

4 000130Z

5 000131Z

2 000132Z

5 000133Z

1 000134Z

5 000135Z

3 000136Z

2 000137Z

1 000138Z

2 000139Z

3 000140Z

2 000141Z

4 000142Z

1 000143Z

4 000144Z

4 000145Z

3 000146Z

4 000147Z

1 000148Z

1 000149Z

1 000150Z

2 000151Z

2 000152Z

2 000153Z

2 000154Z

3 000155Z

3 000156Z

2 000157Z

2 000158Z

1 000160Z

1 000161Z

1 000165Z

1 000166Z

1 000169Z

1 000171Z

1 000177Z

This is on the last 10 minutes of entries, which I expected to be 'kind of' randomly distributed; Instead no entry has a reqstart with a fractional part bigger than .000177, and the vast majority of them has it < .000050

Anybody knows what can be the cause of this, and how to correct it?

Thanks,

dario